Ekaterina Pavlova
2006-Aug-16 16:28 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
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 -------------- next part -------------- An embedded and charset-unspecified text was scrubbed... Name: class_loading_stat.d URL: <mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20060816/5ff47a2d/attachment.ksh> -------------- next part -------------- An embedded and charset-unspecified text was scrubbed... Name: object_allocation_stat.d URL: <mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20060816/5ff47a2d/attachment-0001.ksh>
Peter Cudhea
2006-Aug-16 17:37 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN"> <html> <head> <meta content="text/html;charset=ISO-8859-1" http-equiv="Content-Type"> </head> <body bgcolor="#ffffff" text="#000000"> <p>You should download the tar file of "helper tools" at <a href="blogs.sun.com/roller/page/kamg?entry=example_dtrace_scripts_for_hotspot" target="_top">blogs.sun.com/roller/page/kamg?entry=example_dtrace_scripts_for_hotspot</a> . The helper tools help document the best way to use these hotspot probes. In particular, they document how to work around the gotcha that <code>dtrace -c java</code> does not work, because the hotspot probes do not even exist until java starts up, which is way after dtrace starts up. </p> <br> <br> Ekaterina Pavlova wrote: <blockquote cite="mid44E34795.5060708@sun.com" type="cite">Hello, <br> <br> We have strange problems with using dtrace ''-c'' option. <br> <br> I have very simple object_allocation_stat.d script (attached) which trace hotspot:::object-alloc. <br> These probes are part of HotSpot JVM (JDK 6.0). <br> When I try to run it I observe following error: <br> <br> <blockquote type="cite">object_allocation_stat.d -c "JDK6/bin/java -XX:+ExtendedDTraceProbes -version" <br> </blockquote> 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 <br> <br> <br> However, if I attach object_allocation_stat.d to already running Java process no any errors are happening. <br> <br> At the same time I have similar script called class_loading_stat.d which trace hotspot:::class-[un]loaded probes. <br> When I try to run it I don''t have any errors: <br> <br> <blockquote type="cite">class_loading_stat.d -c "JDK6/bin/java -XX:+ExtendedDTraceProbes -version" <br> </blockquote> Loaded classes by package: <br> 1 java/lang/annotation <br> 1 java/nio/charset/spi <br> 1 sun/net/www <br> 1 sun/net/www/protocol/file <br> 1 sun/net/www/protocol/jar <br> ... <br> <br> The only difference between hotspot:::object-alloc and hotspot:::class-[un]loaded probes is that hotspot:::object-alloc are <br> available only if ExtendedDTraceProbes flag is present (-XX:+ExtendedDTraceProbes). <br> <br> Also, entire hotspot provider, probes, and args are all marked as ''evolving'', not stable, <br> but that doesn''t explain why it works for some of the scripts or when we pause and attach. <br> <br> <br> Does anybody have any ideas why "...matches an unstable set of probes" error is thrown? <br> <br> Thanks a lot, <br> -katya <br> <br> <br> <pre wrap=""> <hr size="4" width="90%"> #!/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 <a class="moz-txt-link-freetext" href="package:\n">package:\n</a>"); printa("%10@d %s\n", @classes_loaded); printf("\n"); printf("Unloaded classes by <a class="moz-txt-link-freetext" href="package:\n">package:\n</a>"); printa("%10@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 <a class="moz-txt-link-freetext" href="package:\n">package:\n</a>"); printa("%10@d %s\n", @classes_loaded); printf("\n"); printf("Unloaded classes by <a class="moz-txt-link-freetext" href="package:\n">package:\n</a>"); printa("%10@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"); } </pre> <pre wrap=""> <hr size="4" width="90%"> #!/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@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@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@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@d %s\n", @allocs_count); printf("\nTotal number of allocated objects: %d\n", ALLOCATED_OBJECTS_CNT); } </pre> <pre wrap=""> <hr size="4" width="90%"> _______________________________________________ dtrace-discuss mailing list <a class="moz-txt-link-abbreviated" href="mailto:dtrace-discuss@opensolaris.org">dtrace-discuss@opensolaris.org</a> </pre> </blockquote> </body> </html>
Ekaterina Pavlova
2006-Aug-16 18:01 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
Yep, these scripts were written by me :) The problem is actually not because the probes are not available at the time dtrace try to attach to java process. (if we had this problem we would have the following error: dtrace: failed to compile script ./object_allocation_stat.d: probe description hotspot1027:::object-alloc does not match any probes ) This problem had place before but now it is possible to specify probes that don''t yet exist that will be enabled when they show up (this feature was added in one of Solaris patches). And this works for all Hotspot probes (all of them are defined in libjvm.so) but for Extended Hotspot probes (available when java flag -XX:+ExtendedDTraceProbes is specified) we have this strange problem: dtrace: failed to compile script ./hotspot/object_allocation_stat.d: args[ ] may not be referenced because probe description hotspot5226:::object-alloc matches an unstable set of probes -katya Peter Cudhea wrote:> You should download the tar file of "helper tools" at > blogs.sun.com/roller/page/kamg?entry=example_dtrace_scripts_for_hotspot > . The helper tools help document the best way to use these hotspot > probes. In particular, they document how to work around the gotcha > that |dtrace -c java| does not work, because the hotspot probes do not > even exist until java starts up, which is way after dtrace starts up. > > > > 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. blogs.sun.com/roller/page/vmrobot
Chip Bennett
2006-Aug-16 23:32 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
Hi Katya, This is the same error that you get when referencing the args array in a probe clause that has a probe specification that matches more than one probe. The actual error code for this message is D_ARGS_MULTI, which makes it seem even more likely. Apparently, since the args array is typed by probe, the D compiler doesn''t know what to do with "args" when the clause is connected to more than one probe. I don''t know if there are other conditions that can cause this error, but just out of curiosity, if you add the "-l" flag to your run, how many probes end up matching "hotspot$target:::object-alloc". This is based on a lot of assumptions on my part, so I could be all wet here. Chip 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
Adam Leventhal
2006-Aug-17 00:10 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
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-- Adam Leventhal, Solaris Kernel Development blogs.sun.com/ahl
Ekaterina Pavlova
2006-Aug-17 08:23 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
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. blogs.sun.com/roller/page/vmrobot
Chip Bennett
2006-Aug-17 08:34 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
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
2006-Aug-17 09:09 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
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. blogs.sun.com/roller/page/vmrobot
Adam Leventhal
2006-Aug-17 16:52 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
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. > blogs.sun.com/roller/page/vmrobot-- Adam Leventhal, Solaris Kernel Development blogs.sun.com/ahl
Ekaterina Pavlova
2006-Aug-17 17:14 UTC
[dtrace-discuss] "dtrace -c" and HotSpot extended probes
Waw, you are right! I didn''t note that in class_loading_stat.d I use argN and in object_allocation_stat.d I use args[N]. That was the problem. I rewrote object_allocation_stat.d to use argN and now it works. Thanks a lot Adam and Chip for so quick problem resolution! -katya Adam Leventhal wrote:>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. >>blogs.sun.com/roller/page/vmrobot >> >-- Ekaterina Pavlova, VMSQE Team, St. Petersburg. blogs.sun.com/roller/page/vmrobot