[dtrace-discuss] "dtrace -c" and HotSpot extended probes
Adam Leventhal
ahl at eng.sun.com
Thu Aug 17 09:52:49 PDT 2006
Ah, in this case, the probes aren't created until some time after the
process has started when the libjvm.so object is opened. When the dtrace(1M)
command starts, there are no probes matching the probe specifier so there's
no way to infer the typed arguments.
Adam
On Thu, Aug 17, 2006 at 01:09:52PM +0400, Ekaterina Pavlova wrote:
> yes, you are right.
> But I cann't get '-l' option work with '-c' option for Hotspot probes.
> I mean that the probes definitions are not yet loaded at the time dtrace
> attaches to the java process and as result I get:
>
> > dtrace -P hotspot\$target -l -c "java -XX:+ExtendedDTraceProbes -version"
> ID PROVIDER MODULE FUNCTION NAME
> dtrace: failed to match hotspot7073:::: No probe matches description
>
>
> I can do only this:
> > dtrace -Z -qc "java -XX:+ExtendedDTraceProbes -version" -n
> 'hotspot\$target:::object-alloc{printf("%s:%s:%s:%s\n", probeprov,
> probemod,
> probefunc, probename);}' |sort |uniq
>
> java version "1.6.0-rc"
> Java(TM) SE Runtime Environment (build 1.6.0-rc-b95)
> Java HotSpot(TM) Client VM (build 1.6.0-rc-b95, mixed mode, sharing)
>
> hotspot7168:libjvm.so:__1cNSharedRuntimeYdtrace_object_alloc_base6FpnGThread_pnHoopDesc__i_:object-alloc
>
>
> -katya
>
> Chip Bennett wrote:
>
> >Hi Katya,
> >
> >If I understood you correctly, you said in your first post that if you
> >attached the D program to an existing process, you didn't get the
> >error. Don't you need to add the "-l" flag to the one where you used
> >"-c" to start the program?
> >
> >Chip
> >
> >Ekaterina Pavlova wrote:
> >
> >>Hmm, I don't think we have multiple probes here.
> >>'dtrace -l' also shows only one object-alloc probe:
> >>
> >>> ./object_allocation_stat.d -p 6934 -l
> >> ID PROVIDER MODULE FUNCTION NAME
> >> 1 dtrace
> >>BEGIN
> >>36258 hotspot6934 libjvm.so
> >>__1cNSharedRuntimeYdtrace_object_alloc_base6FpnGThread_pnHoopDesc__i_
> >>object-alloc
> >>38856 profile
> >>tick-1sec
> >> 6 syscall rexit
> >>entry
> >> 2 dtrace END
> >>
> >>
> >>-katya
> >>
> >>Adam Leventhal wrote:
> >>
> >>>Hi Katya,
> >>>
> >>>As Chip mentioned, if an enabling is associated with multiple probes
> >>>(in this particular case there are apparently several probes in
> >>>different
> >>>locations that match) the args[] array can't work since different
> >>>probes
> >>>might have different arguments. The argN variable are always available.
> >>>
> >>>We've done some work towards addressing this issue, but there's more
> >>>work to be done.
> >>>
> >>>Adam
> >>>
> >>>On Wed, Aug 16, 2006 at 08:28:05PM +0400, Ekaterina Pavlova wrote:
> >>>
> >>>
> >>>>Hello,
> >>>>
> >>>>We have strange problems with using dtrace '-c' option.
> >>>>
> >>>>I have very simple object_allocation_stat.d script (attached) which
> >>>>trace hotspot:::object-alloc.
> >>>>These probes are part of HotSpot JVM (JDK 6.0).
> >>>>When I try to run it I observe following error:
> >>>>
> >>>>
> >>>>
> >>>>>object_allocation_stat.d -c "JDK6/bin/java
> >>>>>-XX:+ExtendedDTraceProbes -version"
> >>>>>
> >>>>
> >>>>dtrace: failed to compile script
> >>>>./hotspot/object_allocation_stat.d: line 53: args[ ] may not be
> >>>>referenced because probe description hotspot5226:::object-alloc
> >>>>matches an unstable set of probes
> >>>>
> >>>>
> >>>>However, if I attach object_allocation_stat.d to already running
> >>>>Java process no any errors are happening.
> >>>>
> >>>>At the same time I have similar script called class_loading_stat.d
> >>>>which trace hotspot:::class-[un]loaded probes.
> >>>>When I try to run it I don't have any errors:
> >>>>
> >>>>
> >>>>
> >>>>>class_loading_stat.d -c "JDK6/bin/java -XX:+ExtendedDTraceProbes
> >>>>>-version"
> >>>>>
> >>>>
> >>>>Loaded classes by package:
> >>>> 1 java/lang/annotation
> >>>> 1 java/nio/charset/spi
> >>>> 1 sun/net/www
> >>>> 1 sun/net/www/protocol/file
> >>>> 1 sun/net/www/protocol/jar
> >>>> ...
> >>>>
> >>>>The only difference between hotspot:::object-alloc and
> >>>>hotspot:::class-[un]loaded probes is that hotspot:::object-alloc are
> >>>>available only if ExtendedDTraceProbes flag is present
> >>>>(-XX:+ExtendedDTraceProbes).
> >>>>
> >>>>Also, entire hotspot provider, probes, and args are all marked as
> >>>>'evolving', not stable,
> >>>>but that doesn't explain why it works for some of the scripts or
> >>>>when we pause and attach.
> >>>>
> >>>>
> >>>>Does anybody have any ideas why "...matches an unstable set of
> >>>>probes" error is thrown?
> >>>>
> >>>>Thanks a lot,
> >>>>-katya
> >>>>
> >>>>
> >>>>
> >>>
> >>>
> >>>
> >>>
> >>>>#!/usr/sbin/dtrace -Zs
> >>>>
> >>>>#pragma D option quiet
> >>>>#pragma D option destructive
> >>>>#pragma D option defaultargs
> >>>>#pragma D option aggrate=100ms
> >>>>
> >>>>/*
> >>>>* Usage:
> >>>>* 1. class_loading_stat.d -c "java ..." INTERVAL_SECS
> >>>>* 2. class_loading_stat.d -p JAVA_PID INTERVAL_SECS
> >>>>*
> >>>>* This script collects statistics about loaded and
> >>>>* unloaded Java classes and dump current state to stdout every
> >>>>INTERVAL_SECS seconds.
> >>>>* If INTERVAL_SECS is not set then 10 seconds interval is used.
> >>>>*
> >>>>*/
> >>>>
> >>>>self char *str_ptr;
> >>>>self string class_name;
> >>>>self string package_name;
> >>>>
> >>>>int INTERVAL_SECS;
> >>>>
> >>>>:::BEGIN
> >>>>{
> >>>> printf("BEGIN Java classes loading tracing\n");
> >>>>
> >>>> INTERVAL_SECS = $1 ? $1 : 10;
> >>>> SAMPLING_TIME = timestamp + INTERVAL_SECS * 1000000000ull;
> >>>>
> >>>> LOADED_CLASSES_CNT = 0;
> >>>> UNLOADED_CLASSES_CNT = 0;
> >>>>}
> >>>>
> >>>>/*
> >>>>* hotspot:::class-loaded, hotspot:::class-unloaded probe arguments:
> >>>>* arg0: char*, class name passed as mUTF8 string
> >>>>* arg1: uintptr_t, class name length
> >>>>* arg2: void*, class loader ID, which is unique identifier for
> >>>>* a class loader in the VM.
> >>>>* arg3: uintptr_t, class is shared or not
> >>>>*/
> >>>>hotspot$target:::class-loaded
> >>>>{
> >>>> LOADED_CLASSES_CNT ++;
> >>>>
> >>>> self->str_ptr = (char*) copyin(arg0, arg1+1);
> >>>> self->str_ptr[arg1] = '\0';
> >>>> self->class_name = (string) self->str_ptr;
> >>>>
> >>>> self->package_name = dirname(self->class_name);
> >>>>
> >>>> /* printf("class-loaded: class=%s, loader=%x\n",
> >>>>self->class_name, arg2); */
> >>>>
> >>>> @classes_loaded[self->package_name] = count();
> >>>>}
> >>>>
> >>>>hotspot$target:::class-unloaded
> >>>>{
> >>>> UNLOADED_CLASSES_CNT ++;
> >>>>
> >>>> self->str_ptr = (char*) copyin(arg0, arg1+1);
> >>>> self->str_ptr[arg1] = '\0';
> >>>> self->class_name = (string) self->str_ptr;
> >>>>
> >>>> self->package_name = dirname(self->class_name);
> >>>>
> >>>> @classes_unloaded[self->package_name] = count();
> >>>>}
> >>>>
> >>>>hotspot$target:::vm-shutdown
> >>>>{
> >>>> exit(0);
> >>>>}
> >>>>
> >>>>syscall::rexit:entry,
> >>>>syscall::exit:entry
> >>>>/pid == $target/
> >>>>{
> >>>> exit(0);
> >>>>}
> >>>>
> >>>>tick-1sec
> >>>>/ timestamp > SAMPLING_TIME /
> >>>>{
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>> printf("%Y\n", walltimestamp);
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>>
> >>>> printf("Loaded classes by package:\n");
> >>>> printa("%10 at d %s\n", @classes_loaded);
> >>>>
> >>>> printf("\n");
> >>>> printf("Unloaded classes by package:\n");
> >>>> printa("%10 at d %s\n", @classes_unloaded);
> >>>>
> >>>> printf("\n");
> >>>> printf("Number of loaded classes: %10d\n", LOADED_CLASSES_CNT);
> >>>> printf("Number of unloaded classes: %10d\n", UNLOADED_CLASSES_CNT);
> >>>>
> >>>> SAMPLING_TIME = timestamp + INTERVAL_SECS * 1000000000ull;
> >>>>}
> >>>>
> >>>>
> >>>>:::END
> >>>>{
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>> printf("%Y\n", walltimestamp);
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>>
> >>>> printf("Loaded classes by package:\n");
> >>>> printa("%10 at d %s\n", @classes_loaded);
> >>>>
> >>>> printf("\n");
> >>>> printf("Unloaded classes by package:\n");
> >>>> printa("%10 at d %s\n", @classes_unloaded);
> >>>>
> >>>> printf("\n");
> >>>> printf("Number of loaded classes: %10d\n", LOADED_CLASSES_CNT);
> >>>> printf("Number of unloaded classes: %10d\n", UNLOADED_CLASSES_CNT);
> >>>>
> >>>> printf("\nEND hotspot tracing.\n");
> >>>>}
> >>>>
> >>>>
> >>>
> >>>
> >>>
> >>>
> >>>>#!/usr/sbin/dtrace -Zs
> >>>>
> >>>>#pragma D option quiet
> >>>>#pragma D option destructive
> >>>>#pragma D option defaultargs
> >>>>#pragma D option bufsize=16m
> >>>>#pragma D option aggrate=100ms
> >>>>
> >>>>/*
> >>>>* Usage:
> >>>>* 1. object_allocation_stat.d -c "java ..." TOP_RESULTS_COUNT
> >>>>INTERVAL_SECS
> >>>>* 2. object_allocation_stat.d -p JAVA_PID TOP_RESULTS_COUNT
> >>>>INTERVAL_SECS
> >>>>*
> >>>>* This script collects statistics about TOP_RESULTS_COUNT (default
> >>>>is 25) object allocations
> >>>>* every INTERVAL_SECS (default is 60) seconds.
> >>>>*
> >>>>* Notes:
> >>>>* - these probes are available only with
> >>>>'-XX:+ExtendedDTraceProbes' option,
> >>>>* so pass this option too.
> >>>>* - This script SLOWS DOWN your java application. So, not be
> >>>>surprised :)
> >>>>*
> >>>>*/
> >>>>
> >>>>self char *str_ptr;
> >>>>self string class_name;
> >>>>
> >>>>long long ALLOCATED_OBJECTS_CNT;
> >>>>
> >>>>int INTERVAL_SECS;
> >>>>
> >>>>:::BEGIN
> >>>>{
> >>>> TOP_RESULTS_COUNT = $1 ? $1 : 25;
> >>>> INTERVAL_SECS = $2 ? $2 : 60;
> >>>>
> >>>> ALLOCATED_OBJECTS_CNT = 0;
> >>>>
> >>>> SAMPLING_TIME = timestamp + INTERVAL_SECS * 1000000000ull;
> >>>>}
> >>>>
> >>>>/*
> >>>>* hotspot:::object-alloc probe arguments:
> >>>>* arg0: uintptr_t, Java thread id
> >>>>* arg1: char*, a pointer to mUTF-8 string containing the
> >>>>name of
> >>>>* the class of the object being allocated
> >>>>* arg2: uintptr_t, the length of the class name (in bytes)
> >>>>* arg3: uintptr_t, the size of the object being allocated
> >>>>*/
> >>>>hotspot$target:::object-alloc
> >>>>{
> >>>> ALLOCATED_OBJECTS_CNT ++;
> >>>>
> >>>> self->str_ptr = (char*) copyin(arg1, args[2]+1);
> >>>> self->str_ptr[args[2]] = '\0';
> >>>> self->class_name = (string) self->str_ptr;
> >>>>
> >>>>
> >>>> @allocs_count[self->class_name] = count();
> >>>> @allocs_size[self->class_name] = sum(args[3]);
> >>>>
> >>>>/*
> >>>> printf("%s:\t[%u] class_name=%s (len=%u), size=%u\n",
> >>>> probename, args[0], self->class_name, args[2], args[3]);
> >>>>*/
> >>>>}
> >>>>
> >>>>tick-1sec
> >>>>/ timestamp > SAMPLING_TIME /
> >>>>{
> >>>> printf("\n");
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>> printf("%Y\n", walltimestamp);
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>> printf("\n");
> >>>> printf("Top %d allocations by size:\n", TOP_RESULTS_COUNT);
> >>>> trunc(@allocs_size, TOP_RESULTS_COUNT);
> >>>> printa("%10 at d %s\n", @allocs_size);
> >>>>
> >>>> printf("\n");
> >>>> printf("Top %d allocations by count:\n", TOP_RESULTS_COUNT);
> >>>> trunc(@allocs_count, TOP_RESULTS_COUNT);
> >>>> printa("%10 at d %s\n", @allocs_count);
> >>>>
> >>>> printf("\nTotal number of allocated objects: %d\n",
> >>>>ALLOCATED_OBJECTS_CNT);
> >>>>
> >>>> SAMPLING_TIME = timestamp + INTERVAL_SECS * 1000000000ull;
> >>>>}
> >>>>
> >>>>
> >>>>syscall::rexit:entry,
> >>>>syscall::exit:entry
> >>>>/pid == $target/
> >>>>{
> >>>> exit(0);
> >>>>}
> >>>>
> >>>>:::END
> >>>>{
> >>>> printf("\n");
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>> printf("%Y\n", walltimestamp);
> >>>>
> >>>>printf("------------------------------------------------------------------------\n");
> >>>>
> >>>>
> >>>> printf("\n");
> >>>> printf("Top %d allocations by size:\n", TOP_RESULTS_COUNT);
> >>>> trunc(@allocs_size, TOP_RESULTS_COUNT);
> >>>> printa("%10 at d %s\n", @allocs_size);
> >>>>
> >>>> printf("\n");
> >>>> printf("Top %d allocations by count:\n", TOP_RESULTS_COUNT);
> >>>> trunc(@allocs_count, TOP_RESULTS_COUNT);
> >>>> printa("%10 at d %s\n", @allocs_count);
> >>>>
> >>>> printf("\nTotal number of allocated objects: %d\n",
> >>>>ALLOCATED_OBJECTS_CNT);
> >>>>}
> >>>>
> >>>>
> >>>
> >>>
> >>>
> >>>
> >>>>_______________________________________________
> >>>>dtrace-discuss mailing list
> >>>>dtrace-discuss at opensolaris.org
> >>>>
> >>>
> >>>
> >>>
> >>>
> >>
> >
>
> --
> Ekaterina Pavlova,
> VMSQE Team, St. Petersburg.
> http://blogs.sun.com/roller/page/vmrobot
--
Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
More information about the dtrace-discuss
mailing list