[dtrace-discuss] "dtrace -c" and HotSpot extended probes

[Ekaterina Pavlova]

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 --------------
#!/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");
}

-------------- next part --------------
#!/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);
}