dtrace discuss - Jan 2008 - Hotspot provider probes not getting cleaned up

Howdy,

I received the following error today when I attempted to run a DTrace
script that uses the Java hotspot provider:

$ dtrace -s dbmethodprofile.d
dtrace: failed to compile script methods.d: line 15: probe description
:::method-entry does not match any probes

The Java process that I was attempting to trace was started with the
"-XX:+DTraceMethodProbes" option, so the method-* probes should be
available.  When I did a bit of digging, I noticed that the hotspot
probes were still enabled  after the process exited:

$ ps -ef | grep java
    root  6988  6803   0 01:43:53 pts/1       0:00 grep java

$ dtrace -l | grep hotspot |more
 3515 hotspot10316         libjvm.so
__1cTClassLoadingServiceTnotify_class_loaded6FpnNinstanceKlass_b_v_
clas
s-loaded
 3516 hotspot10316         libjvm.so
__1cTClassLoadingServiceVnotify_class_unloaded6FpnNinstanceKlass__v_
cla
ss-unloaded
 3517 hotspot10316         libjvm.so
__1cHnmethodbFpost_compiled_method_load_event6M_v_
compiled-method-load
 3518 hotspot10316         libjvm.so
__1cHnmethodbBpost_compiled_method_unload6M_v_ compiled-method-unload
 3519 hotspot10316         libjvm.so
__1cHnmethodbAmake_not_entrant_or_zombie6Mi_v_ compiled-method-unload
 3520 hotspot10316         libjvm.so
__1cVVM_ParallelGCSystemGCEdoit6M_v_ gc-begin
 3521 hotspot10316         libjvm.so
__1cbMVM_ParallelGCFailedPermanentAllocationEdoit6M_v_ gc-begin
 3522 hotspot10316         libjvm.so
__1cbDVM_ParallelGCFailedAllocationEdoit6M_v_ gc-begin
 3523 hotspot10316         libjvm.so  __1cRVM_GenCollectFullEdoit6M_v_ gc-begin
 3524 hotspot10316         libjvm.so
__1cbAVM_GenCollectForAllocationEdoit6M_v_ gc-begin
     < ..... >

I checked on another box, and the hotspot probes disappeared after the
Java process exited. Has anyone encountered this bizarre scenario
before? I checked the OpenSolaris and Java bug database, but wasn''t
able to find an issue that matched the symptoms listed above. The
software in question is Java 6 update 3 and X64 Solaris 10 update 3.
If this is a known issue, could someone reply with the bugid? If this
is an unknown issue, I will open a ticket with Sun support (I made
sure to snag a core file prior to rebooting the server to remove the
ghost probes).

Thanks for any insight,
- Ryan
-- 
UNIX Administrator
http://prefetch.net

Matty wrote:
> Howdy,
>
> I received the following error today when I attempted to run a DTrace
> script that uses the Java hotspot provider:
>
> $ dtrace -s dbmethodprofile.d
> dtrace: failed to compile script methods.d: line 15: probe description
> :::method-entry does not match any probes
>   
Not sure what your script is doing, but did you try writing it like this:

hotspot$target:::method-entry { ... }

... and executing like this:

dtrace -s dbmethodprofile.d -p <pid>

Does that work?
> The Java process that I was attempting to trace was started with the
> "-XX:+DTraceMethodProbes" option, so the method-* probes should
be
> available.  When I did a bit of digging, I noticed that the hotspot
> probes were still enabled  after the process exited:
>
> $ ps -ef | grep java
>     root  6988  6803   0 01:43:53 pts/1       0:00 grep java
>
> $ dtrace -l | grep hotspot |more
>  3515 hotspot10316         libjvm.so
> __1cTClassLoadingServiceTnotify_class_loaded6FpnNinstanceKlass_b_v_
> clas
> s-loaded
>  3516 hotspot10316         libjvm.so
> __1cTClassLoadingServiceVnotify_class_unloaded6FpnNinstanceKlass__v_
> cla
> ss-unloaded
>  3517 hotspot10316         libjvm.so
> __1cHnmethodbFpost_compiled_method_load_event6M_v_
> compiled-method-load
>  3518 hotspot10316         libjvm.so
> __1cHnmethodbBpost_compiled_method_unload6M_v_ compiled-method-unload
>  3519 hotspot10316         libjvm.so
> __1cHnmethodbAmake_not_entrant_or_zombie6Mi_v_ compiled-method-unload
>  3520 hotspot10316         libjvm.so
> __1cVVM_ParallelGCSystemGCEdoit6M_v_ gc-begin
>  3521 hotspot10316         libjvm.so
> __1cbMVM_ParallelGCFailedPermanentAllocationEdoit6M_v_ gc-begin
>  3522 hotspot10316         libjvm.so
> __1cbDVM_ParallelGCFailedAllocationEdoit6M_v_ gc-begin
>  3523 hotspot10316         libjvm.so  __1cRVM_GenCollectFullEdoit6M_v_
gc-begin
>  3524 hotspot10316         libjvm.so
> __1cbAVM_GenCollectForAllocationEdoit6M_v_ gc-begin
>      < ..... >
>   
What was the pid of the java process that went away?  Could it be that a 
different process (10316) is running and providing those probes?  
libjvm.so and the hotspot provider aren''t necessarily only linked to
the
''java'' executable - browsers and other launchers can load
libjvm.so and
this would register probes like this as well.
> I checked on another box, and the hotspot probes disappeared after the
> Java process exited. Has anyone encountered this bizarre scenario
> before? I checked the OpenSolaris and Java bug database, but
wasn''t
> able to find an issue that matched the symptoms listed above. The
> software in question is Java 6 update 3 and X64 Solaris 10 update 3.
> If this is a known issue, could someone reply with the bugid? If this
> is an unknown issue, I will open a ticket with Sun support (I made
> sure to snag a core file prior to rebooting the server to remove the
> ghost probes).
>
> Thanks for any insight,
> - Ryan
>

On Jan 3, 2008 9:32 PM, Keith McGuigan <Keith.McGuigan at sun.com>
wrote:
> Matty wrote:
> > Howdy,
> >
> > I received the following error today when I attempted to run a DTrace
> > script that uses the Java hotspot provider:
> >
> > $ dtrace -s dbmethodprofile.d
> > dtrace: failed to compile script methods.d: line 15: probe description
> > :::method-entry does not match any probes
> >
> Not sure what your script is doing, but did you try writing it like this:
It was using a probe similar to the following:

hotspot*:::method-entry
/ ... /
{}

The script worked fine after I rebooted the server, so I don''t think
the script is to blame.
> > The Java process that I was attempting to trace was started with the
> > "-XX:+DTraceMethodProbes" option, so the method-* probes
should be
> > available.  When I did a bit of digging, I noticed that the hotspot
> > probes were still enabled  after the process exited:
> >
> > $ ps -ef | grep java
> >     root  6988  6803   0 01:43:53 pts/1       0:00 grep java
> >
> > $ dtrace -l | grep hotspot |more
> >  3515 hotspot10316         libjvm.so
> > __1cTClassLoadingServiceTnotify_class_loaded6FpnNinstanceKlass_b_v_
> > clas
> > s-loaded
> >  3516 hotspot10316         libjvm.so
> > __1cTClassLoadingServiceVnotify_class_unloaded6FpnNinstanceKlass__v_
> > cla
> > ss-unloaded
> >  3517 hotspot10316         libjvm.so
> > __1cHnmethodbFpost_compiled_method_load_event6M_v_
> > compiled-method-load
> >  3518 hotspot10316         libjvm.so
> > __1cHnmethodbBpost_compiled_method_unload6M_v_ compiled-method-unload
> >  3519 hotspot10316         libjvm.so
> > __1cHnmethodbAmake_not_entrant_or_zombie6Mi_v_ compiled-method-unload
> >  3520 hotspot10316         libjvm.so
> > __1cVVM_ParallelGCSystemGCEdoit6M_v_ gc-begin
> >  3521 hotspot10316         libjvm.so
> > __1cbMVM_ParallelGCFailedPermanentAllocationEdoit6M_v_ gc-begin
> >  3522 hotspot10316         libjvm.so
> > __1cbDVM_ParallelGCFailedAllocationEdoit6M_v_ gc-begin
> >  3523 hotspot10316         libjvm.so  __1cRVM_GenCollectFullEdoit6M_v_
gc-begin
> >  3524 hotspot10316         libjvm.so
> > __1cbAVM_GenCollectForAllocationEdoit6M_v_ gc-begin
> >      < ..... >
> >
>
> What was the pid of the java process that went away?  Could it be that a
> different process (10316) is running and providing those probes?
> libjvm.so and the hotspot provider aren''t necessarily only linked
to the
> ''java'' executable - browsers and other launchers can load
libjvm.so and
> this would register probes like this as well.
I am not 100% sure what the PID was, but I am certain there were no
Java processes running (at least according to ps). After I rebooted
the server, everything worked flawlessly. Unless anyone has any ideas,
I will open up a ticket with Sun support. This appears to be some sort
of bug.

Thanks,
- Ryan
-- 
UNIX Administrator
http://prefetch.net

Matty wrote:
>
> I am not 100% sure what the PID was, but I am certain there were no
> Java processes running (at least according to ps). After I rebooted
> the server, everything worked flawlessly. Unless anyone has any ideas,
> I will open up a ticket with Sun support. This appears to be some sort
> of bug.
>   
The hotspot probes you referenced aren''t tied to the
''java'' executable.
They''re created when the ''libjvm.so'' library is
loaded (they are
traditional USDT probes in that library).  The ''java''
executable isn''t
the only thing that loads libjvm.so.  So not having ''ps'' list
a ''java''
process, while dtrace still shows some ''hotspot*'' probes
doesn''t
necessarily indicate a problem.   Your reboot may have fixed things 
because it terminated some other unrelated process that may have loaded 
libjvm.so (perhaps a browser?)

Just make sure to take a close look at the pid of the java process 
you''re starting (and stopping), and make sure that the
hotspot<pid>
provider of the leftover probes matches that pid.   What were you doing 
that caused this situation to occur?

--
- Keith

On Jan 3, 2008 10:25 PM, Matty <matty91 at gmail.com>
wrote:
> I am not 100% sure what the PID was, but I am certain there were no
> Java processes running (at least according to ps). After I rebooted
> the server, everything worked flawlessly. Unless anyone has any ideas,
> I will open up a ticket with Sun support. This appears to be some sort
> of bug.
C programs that have USDT probes get linked with drti.o.  Notice that
to register and unregister the USDT probes, drti.c[1] does the
following in ini and fini functions.

   fd = open(/dev/dtrace/helper, ...)
   ioctl(fd, ...)
   close(fd)

Assuming that Java is using this same mechanism, it suggests to me
that the fini function was not called or failed.  Would it be called
if the java process was killed in a bad way (e.g. SIGSEGV, SIGKILL)?
Is it possible that the process could be out of file descriptors when
the open() call happens in fini?

Perhaps there is a need (maybe already exists) a hook in the kernel
code called during process cleanup to do the equivalent of
ioctl(fd, DTRACEHIOC_REMOVE, gen) from within the kernel just in case
the user space code fails.

1.http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libdtrace/common/drti.c

-- 
Mike Gerdts
http://mgerdts.blogspot.com/

On Jan 4, 2008 8:49 AM, Keith McGuigan <Keith.McGuigan at sun.com>
wrote:
> Matty wrote:
> >
> > I am not 100% sure what the PID was, but I am certain there were no
> > Java processes running (at least according to ps). After I rebooted
> > the server, everything worked flawlessly. Unless anyone has any ideas,
> > I will open up a ticket with Sun support. This appears to be some sort
> > of bug.
> >
> The hotspot probes you referenced aren''t tied to the
''java'' executable.
> They''re created when the ''libjvm.so'' library is
loaded (they are
> traditional USDT probes in that library).  The ''java''
executable isn''t
> the only thing that loads libjvm.so.  So not having ''ps''
list a ''java''
> process, while dtrace still shows some ''hotspot*'' probes
doesn''t
> necessarily indicate a problem.   Your reboot may have fixed things
> because it terminated some other unrelated process that may have loaded
> libjvm.so (perhaps a browser?)
I am 100% certain that the ''java'' executable is the only thing
that
makes use of libjvm.so
on this specific server. Since my script didn''t work prior to me
rebooting the box, and it
started working after I rebooted the box, it would appear to me that
some type of bug
reared its head.
> Just make sure to take a close look at the pid of the java process
> you''re starting (and stopping), and make sure that the
hotspot<pid>
> provider of the leftover probes matches that pid.   What were you doing
> that caused this situation to occur?
We have bumped into a couple bugs in the JVM CMS collector that cause
our Java processes
to fail hard. This is the only thing I can think of that might lead to
this behavior.

Thanks for the feedback,
- Ryan
-- 
UNIX Administrator
http://prefetch.net