Solved DTrace, OpenJDK12

dinsdale

dinsdale

Hi,

I'm running minecraft server on an older 32 core AMD server. I've been running 1.12.2 successfully for some time now and any given Minecraft instance only uses a fraction of a percent of CPU time with no users, and usually only a percent or two with 2-3 users.

I've started running Minecraft 1.14 and the performance is abysmal. With nobody on the server it uses 100% of a CPU and has > 2GB in resident memory. Yikes.

Anyway, my thought was I would take this opportunity to learn more DTrace since I've had Brennan Greggs book sitting around for some years. The problem is I can't seem to find any Java providers?

I've done kldload dtraceall and then searched with dtrace -l | grep ... and haven't found anything using grep hints like jni, jvm or java.

I've installed OpenJDK12 from pkg but I still don't see any providers. So this brings me to some questions:
- Has anyone one the forums used OpenJDK12 with DTrace that could point me in the right direction? Google doesn't seem to have any suggestions...
- Does anyone know if OpenJDK12 from pkg has the DTrace providers compiled in?
- Are there even any providers for OpenJDK12?

I'm pretty much drowning at this point so any suggestions are welcome.

Thanks in advance,
Dinsdale
 
dinsdale said:
- Does anyone know if OpenJDK12 from pkg has the DTrace providers compiled in?
Click to expand...
normally, yes, its implemented .
sometimes during the different build-tests its disabled. depends on the platform..

you can ask e.g Michael-O or acheron if they`ve got time , whether they made extensive tests with dtrace( I haven't) ..
say regards to them from me ;-)
 
.. I made a quick&dirty test(jdk12 installed from pkg) :

Code: 
root@freebsd:~ # uname -a
FreeBSD freebsd 12.0-RELEASE-p2 FreeBSD 12.0-RELEASE-p2 GENERIC  amd64
root@freebsd:~ # java -version
openjdk version "12" 2019-04-16
OpenJDK Runtime Environment (build 12+12-2)
OpenJDK 64-Bit Server VM (build 12+12-2, mixed mode)
root@freebsd:~ # dtrace -l | wc -l
   78319
root@freebsd:~ # cat example.d
syscall:::
/probefunc!="write" && execname=="java"/
{
    printf("probefunc:%s, pid:%d, execname:%s\n",probefunc, pid, execname);
}
root@freebsd:~ # dtrace -qs example.d
probefunc:poll, pid:1660, execname:java
probefunc:recvmsg, pid:1660, execname:java
probefunc:recvmsg, pid:1660, execname:java
probefunc:recvmsg, pid:1660, execname:java
probefunc:recvmsg, pid:1660, execname:java
probefunc:poll, pid:1660, execname:java
probefunc:_umtx_op, pid:1664, execname:java
probefunc:_umtx_op, pid:1664, execname:java
probefunc:_umtx_op, pid:1660, execname:java
probefunc:_umtx_op, pid:1660, execname:java
probefunc:poll, pid:1660, execname:java
......
... blablabla....


Code: 
root@freebsd:~ # cat example3.d
#!/usr/sbin/dtrace -qs

pid$1:libc:malloc:entry
{
    @stack_count[ustack(4)] = count() ;
}
root@freebsd:~ # ./example3.d 1660
^C


              libc.so.7`malloc+0x1
              libX11.so.6.3.0`XSetClassHint+0x67
              libgdk-x11-2.0.so.0.2400.32`0x88e8471a4
              libgdk-x11-2.0.so.0.2400.32`gdk_window_new+0x41a
                1

              libc.so.7`malloc+0x1
              libglib-2.0.so.0.5600.3`g_malloc+0x16
              libglib-2.0.so.0.5600.3`g_strdup+0x29
              libgtk-x11-2.0.so.0.2400.32`gtk_widget_path+0x19a
                1

             ......
.....
 libc.so.7`malloc+0x1


              libglass.so`Java_com_sun_glass_ui_gtk_GtkApplication__1submitForLaterInvocation+0x1a


              libzip.so`0x80293b45c


              libzip.so`0x80293b07d


              196

.....
....blablabla
 
Thanks for looking into that, I really appreciate it. I'll definitely look at some standard dtrace probes, but I was trying to look into the java specific probes. I was looking into the OpenDTrace toolkit found here: https://github.com/opendtrace/toolkit. An example is the j_thread.d script: https://github.com/opendtrace/toolkit/blob/master/Java/j_thread.d:
Code: 
[snip]
hotspot*:::thread-start
{
    this->thread = (char *)copyin(arg0, arg1 + 1);
    this->thread[arg1] = '\0';
    printf("%-20Y  %6d/%-5d => %s\n", walltimestamp, pid, tid,
        stringof(this->thread));
}
[snip]

But there doesn't seem to be a hotspot provider?

Code: 
root@sylvester:/home/russellh/dtrace-scripts # uname -a
FreeBSD sylvester 12.0-RELEASE-p3 FreeBSD 12.0-RELEASE-p3 r346787 GENERIC  amd64
root@sylvester:/home/russellh/git/opendtrace-toolkit/Java # dtrace -l | grep hotspot
root@sylvester:/home/russellh/git/opendtrace-toolkit/Java #

Here are the top 4 processes on my server according to top:

Code: 
  PID   JID USERNAME    THR PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
92671    14 russellh     51  20    0  5197M  2342M uwait   22  60.1H  98.30% java
96391    18 russellh     70  21    0  8720M  1074M uwait   20 850:25  98.09% java
17550    18 russellh     37  20    0  8108M   293M uwait    3   9:17   0.42% java
23105     7 russellh     28  52    0   848M    22M uwait   20 263:46   0.27% mongod
1473     0 root          1  20    0    13M  3820K CPU15   15   0:00   0.08% top
...

(PID 9271 and 96391 are both instances of Minecraft 1.14.3 under OpenJDK12. They have only been running since last night and have accumulated very high total time on the CPU. Conversely 17550 is Minecraft 1.12 under JRE8 and it's been running since Thursday. Its an absolutely huge map but still only has 293M resident. 96391 is a standard map that I've never played so it should be tiny, but it's 1074m.)

So I tried running the script:
root@sylvester:/home/russellh/git/opendtrace-toolkit/Java # ./j_thread.d
TIME PID/TID -- THREAD

[crickets]

I tried putting garbage as a provider name instead of hotspot*and the script still ran with the same effect.

So where are all the Java providers??? I just saw a readme note in the toolkit/Java folder that indicates I need to run java -XX:+ExtendedDTraceProbes ... . I'll try that soon (it's bedtime now!) and see if that improves anything?

Anyway, your little example.d script whetted my whistle:
Code: 
root@sylvester:/home/russellh/dtrace-scripts # cat /tmp/test.txt | less
probefunc:clock_gettime, pid:92671, execname:java
probefunc:_umtx_op, pid:96391, execname:java
probefunc:clock_gettime, pid:92671, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:_umtx_op, pid:92671, execname:java
probefunc:_umtx_op, pid:92671, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:clock_gettime, pid:92671, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:clock_gettime, pid:92671, execname:java
probefunc:_umtx_op, pid:96391, execname:java
probefunc:clock_gettime, pid:92671, execname:java
probefunc:_umtx_op, pid:96391, execname:java
probefunc:clock_gettime, pid:92671, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:clock_gettime, pid:92671, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:clock_gettime, pid:92671, execname:java
probefunc:clock_gettime, pid:96391, execname:java
probefunc:_umtx_op, pid:92671, execname:java
probefunc:clock_gettime, pid:96391, execname:java

Holy clock watcher batman!

Thanks again for your help,
Dinsdale
 
dinsdale said:
So where are all the Java providers??? I just saw a readme note in the toolkit/Java folder that indicates I need to run java -XX:+ExtendedDTraceProbes ... .
Click to expand...

Exactly !
Here we go :
Code: 
root@freebsd:~/Desktop/demo/jfc/Notepad # uname -a
FreeBSD freebsd 12.0-RELEASE-p2 FreeBSD 12.0-RELEASE-p2 GENERIC  amd64
--
root@freebsd:~/Desktop/demo/jfc/Notepad # java -version
openjdk version "12" 2019-04-16
OpenJDK Runtime Environment (build 12+12-2)
OpenJDK 64-Bit Server VM (build 12+12-2, mixed mode)
--
root@freebsd:~/Desktop/demo/jfc/Notepad # java -XX:+ExtendedDTraceProbes -jar Notepad.jar
--
root@freebsd:~/Desktop/demo/jfc/Notepad # dtrace -n 'hotspot$1:::gc-end{printf("GC: %d\n", timestamp);}' 2361
dtrace: description 'hotspot$1:::gc-end' matched 4 probes
--
root@freebsd:~/Desktop/demo/jfc/Notepad # dtrace -l 2361 | grep hotspot
78319 hotspot_jni2361         libjvm.so                   jni_AllocObject AllocObject-entry
78320 hotspot_jni2361         libjvm.so                   jni_AllocObject AllocObject-return
78321 hotspot_jni2361         libjvm.so           jni_AttachCurrentThread AttachCurrentThread-entry
78322 hotspot_jni2361         libjvm.so           jni_AttachCurrentThread AttachCurrentThread-return
78323 hotspot_jni2361         libjvm.so   jni_AttachCurrentThreadAsDaemon AttachCurrentThreadAsDaemon-entry
78324 hotspot_jni2361         libjvm.so   jni_AttachCurrentThreadAsDaemon AttachCurrentThreadAsDaemon-return
78325 hotspot_jni2361         libjvm.so             jni_CallBooleanMethod CallBooleanMethod-entry
78326 hotspot_jni2361         libjvm.so             jni_CallBooleanMethod CallBooleanMethod-return
78327 hotspot_jni2361         libjvm.so            jni_CallBooleanMethodA CallBooleanMethodA-entry
... blablabla   

78847 hotspot2361         libjvm.so _ZN8VMThread18evaluate_operationEP12VM_Operation vmops-begin
78848 hotspot2361         libjvm.so _ZN8VMThread18evaluate_operationEP12VM_Operation vmops-end
78849 hotspot2361         libjvm.so _ZN16VMOperationQueue3addEP12VM_Operation vmops-request
 
Okay, I clearly do not understand how DTrace finds and loads providers. In hindsight I suppose it makes sense that all possible providers wouldn't be available at all times. It probably says something about that in the Brendan Greggs book so I shall re-read the opening chapters.

Thank you again ucomp, your guidance has been invaluable.

Dinsdale
 
Ha ha. They fixed the bug in Minecraft server 14.4. I'm actually a little sad they did, I haven't had a chance to look at this again until now. I supposed now I can trace both processes and compare them!
 
You must log in or register to reply here.
Back
Top