Gather troubleshooting information from a Java process for Puppet Enterprise

Puppet Server and PE services run on the JVM (Java virtual machine). When PE is unresponsive or has performance issues, you can use built-in tools in Java to get troubleshooting information.

Use the tools to find out:

• What’s happening to Java threads
• What led up to a deadlock
• Why the CPU is busy
• Which threads have high CPU usage
• How a Java process uses RAM
• How many JRuby processes are present
• Which garbage collector is being used
• How the garbage collector has divided up heap space
• How to generate a heap dump (.hprof file) without waiting for an OutOfMemory error

Attach the information you gather to your support ticket to help us troubleshoot your issues.

Version and installation information

PE version: All supported versions

Solution

Java tools overview

Install Java development tools

In versions of PE earlier than 2018.1, the Java development tools in the table above were installed by default. In PE 2018.1 or later, they must be installed before you can use them. Install the tools on the node where you’d like to use them. Run:

puppet resource package pe-java11-devel ensure=installed

The next section walks you through how to use these tools; for information on forming commands, see the Example commands section; for detailed information about each tool, see the Java diagnostic tools section.

The command template

The tools discussed in this article share a common execution pattern:

su - <service account> -s /bin/bash -c '<path to the PE Java /bin directory>/<java tool> <options> <service PID>'

Let's step through each component to help you form the command.

su

Why use su instead of sudo?

The sudo command is usually shorter to invoke than su. However, some environments restrict which commands can be used with sudo, even by root. The su command is longer but sidesteps this restriction.

Service account

The tools covered in this article can only be run by the process owner, in this case the service account. There are no exceptions, not even for root. If you try to run these tools as another user, you’ll throw a permissions error.

The service account is the user account used to run a service. For example, pe-puppet is the user account for the pe-puppetserver service and pe-puppetdb is the user account for the pe-puppetdb service.

PE services and user accounts list.

Note: The latest version of our documentation is linked, please navigate to the right version for your deployment.

Paths and service accounts are (for the most part) the same for all versions of PE.

The path to the PE Java /bin directory

For PE 2019.2 and later, the path to the PE Java /bin directory is /opt/puppetlabs/server/apps/java/lib/jvm/java/bin/

Java tools and options

The tools are located in the Java /bin directory. See the Java diagnostic tools section for information on tool options.

Service PID

The process ID of the service.

For SysV init systems, including CentOS 6 and earlier, SLES 11 and earlier, Ubuntu 14.04 and earlier, the PID is in a file under /var/run. View the PID by running:

$(cat /var/run/puppetlabs/<service name>/<service name>)

In systemd init systems such as CentOS 7, SLES 12, Ubuntu 16.04, get the PID by running the systemctl command:

$(systemctl show -p MainPID <service name>|cut -d= -f2)

Example commands

Run the jstack tool against the pe-puppetserver service from PE 2023.0 on Ubuntu 18:

su - pe-puppet -s /bin/bash -c '/opt/puppetlabs/server/apps/java/lib/jvm/java/bin/jstack $(systemctl show -p MainPID pe-puppetserver|cut -d= -f2)'

Run the jmap tool against the pe-puppetdb service for SysV init based systems:

su - pe-puppetdb -s /bin/bash -c '/opt/puppetlabs/server/apps/java/lib/jvm/java/bin/jmap -histo:live $(cat /var/run/puppetlabs/puppetdb/puppetdb)'

Java diagnostic tools

The jstack tool

The jstack tool outputs backtraces showing each thread in the JVM, what the thread is doing, and the series of function calls that led it to do that.

Use jstack to answer the following questions:

• A Java service is non-responsive. What is happening in the CPU?
• What’s happening to Java threads?
• I have a deadlock, what led up to it?
• Why is the CPU so busy?

For example:

# su - pe-puppet -s /bin/bash -c '/opt/puppetlabs/server/apps/java/lib/jvm/java/bin/jstack $(systemctl show -p MainPID pe-puppetserver|cut -d= -f2)'

Full thread dump OpenJDK 64-Bit Server VM (24.85-b03 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007faf18001000 nid=0x291d waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

...

"main" prio=10 tid=0x00007faf4c009000 nid=0x7f6e waiting on condition [0x00007faf52eed000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000d15cfee0> (a java.util.concurrent.CountDownLatch$Sync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
    at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:236)
    at clojure.core$promise$reify__6363.deref(core.clj:6553)
    at clojure.core$deref.invoke(core.clj:2200)
    at puppetlabs.trapperkeeper.internal$shutdown_service$reify__5401$service_fnk__4090__auto___positional$reify__5406.wait_for_shutdown(internal.clj:291)
    at puppetlabs.trapperkeeper.internal$wait_for_app_shutdown.invoke(internal.clj:376)
    at puppetlabs.trapperkeeper.core$run_app.invoke(core.clj:130)
    at puppetlabs.trapperkeeper.core$run.invoke(core.clj:148)
    at puppetlabs.trapperkeeper.core$main.doInvoke(core.clj:159)
    at clojure.lang.RestFn.invoke(RestFn.java:457)
    at clojure.lang.Var.invoke(Var.java:394)
    at clojure.lang.AFn.applyToHelper(AFn.java:165)
    at clojure.lang.Var.applyTo(Var.java:700)
    at clojure.core$apply.invoke(core.clj:624)
    at puppetlabs.trapperkeeper.main$_main.doInvoke(main.clj:7)
    at clojure.lang.RestFn.invoke(RestFn.java:457)
    at clojure.lang.Var.invoke(Var.java:394)
    at clojure.lang.AFn.applyToHelper(AFn.java:165)
    at clojure.lang.Var.applyTo(Var.java:700)
    at clojure.core$apply.invoke(core.clj:624)
    at clojure.main$main_opt.invoke(main.clj:315)
    at clojure.main$main.doInvoke(main.clj:420)
    at clojure.lang.RestFn.invoke(RestFn.java:512)
    at clojure.lang.Var.invoke(Var.java:409)
    at clojure.lang.AFn.applyToHelper(AFn.java:178)
    at clojure.lang.Var.applyTo(Var.java:700)
    at clojure.main.main(main.java:37)
"VM Thread" prio=10 tid=0x00007faf4c074800 nid=0x7f78 runnable
"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007faf4c01e800 nid=0x7f72 runnable
"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007faf4c020800 nid=0x7f73 runnable
"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007faf4c022000 nid=0x7f76 runnable
"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007faf4c024000 nid=0x7f77 runnable
"VM Periodic Task Thread" prio=10 tid=0x00007faf4c0b0000 nid=0x7f80 waiting on condition

The Unix top utility

Get a thread-level breakdown of CPU usage by using the Unix top utility with the -H flag.

Use the top utility in combination with output from jstack to answer the following question:

• The Java service is responsive but uses a lot of CPU. Which threads have high CPU usage?

Convert the PID values returned by top to hexadecimal and match them with the nid= (Java native ID) field in the header of each jstack backtrace.

# top -H -b -n1 -p $(systemctl show -p MainPID pe-puppetserver|cut -d= -f2)

top - 02:25:18 up 27 days, 23:10,  3 users,  load average: 0.05, 0.04, 0.08
Threads:  28 total,   0 running,  28 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.9 us,  0.4 sy,  0.0 ni, 96.5 id,  1.2 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   3883300 total,  3671100 used,   212200 free,      328 buffers
KiB Swap:        0 total,        0 used,        0 free.   235272 cached Mem
  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
  340 pe-pupp+  20   0 3297712 742340   8040 D  6.6 19.1   2:38.82 java
32618 pe-pupp+  20   0 3297712 742340   8040 S  0.0 19.1   0:00.00 java
32622 pe-pupp+  20   0 3297712 742340   8040 S  0.0 19.1   0:11.46 java
32626 pe-pupp+  20   0 3297712 742340   8040 S  0.0 19.1   0:15.40 java
...

The jmap tool

Use the jmap tool to inspect JVM memory usage and determine what a Java process is doing with RAM.

jmap supports several invocation options:

Using jmap -heap

The -heap option prints a summary that shows which garbage collector is being used and how that collector has divided the heap space.

Note: In PE 2023.0, jmap -heap is deprecated. However, it might work in earlier versions. If it is deprecated in your version, when you run the command, you get the following error:

Error: -heap option used
Cannot connect to core dump or remote debug server. Use jhsdb jmap instead

To run the command:

# su - pe-puppet -s /bin/bash -c '/opt/puppetlabs/server/apps/java/lib/jvm/java/bin/jmap -heap $(systemctl show -p MainPID pe-puppetserver|cut -d= -f2)'

Attaching to process ID 32618, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.85-b03
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
   MinHeapFreeRatio = 0
   MaxHeapFreeRatio = 100
   MaxHeapSize      = 805306368 (768.0MB)
   NewSize          = 1310720 (1.25MB)
   MaxNewSize       = 17592186044415 MB
   OldSize          = 5439488 (5.1875MB)
   NewRatio         = 2
   SurvivorRatio    = 8
   PermSize         = 21757952 (20.75MB)
   MaxPermSize      = 174063616 (166.0MB)
   G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
   capacity = 191365120 (182.5MB)
   used     = 162101744 (154.59226989746094MB)
   free     = 29263376 (27.907730102539062MB)
   84.70809309449915% used
From Space:
   capacity = 8388608 (8.0MB)
   used     = 2490368 (2.375MB)
   free     = 5898240 (5.625MB)
   29.6875% used
To Space:
   capacity = 14680064 (14.0MB)
   used     = 0 (0.0MB)
   free     = 14680064 (14.0MB)
   0.0% used
PS Old Generation
   capacity = 366477312 (349.5MB)
   used     = 333528408 (318.07747650146484MB)
   free     = 32948904 (31.422523498535156MB)
   91.00929227509724% used
PS Perm Generation
   capacity = 87031808 (83.0MB)
   used     = 84792072 (80.86402130126953MB)
   free     = 2239736 (2.1359786987304688MB)
   97.42653168827654% used

53341 interned Strings occupying 5009152 bytes.

Using jmap -histo:live

Using the -histo:live option generates a histogram of the heap and causes a full garbage collection of the JVM. The list generated contains the objects that survived garbage collection. The list is grouped by class and includes, in bytes, how much memory each class is using. This invocation is lightweight, generating a small text file. It provides information such as the number of JRuby processes present.

If you are diagnosing a memory leak, use the live option.

# su - pe-puppet -s /bin/bash -c '/opt/puppetlabs/server/apps/java/lib/jvm/java/bin/jmap -histo:live $(systemctl show -p MainPID pe-puppetserver|cut -d= -f2)'

If you are diagnosing large objects committed to the heap or want to see what’s in the heap, do not use the live option.

su - pe-puppet -s /bin/bash -c '/opt/puppetlabs/server/apps/java/lib/jvm/java/bin/jmap -histo $(systemctl show -p MainPID pe-puppetserver|cut -d= -f2)'

num     #instances         #bytes  class name
----------------------------------------------
   1:        253108       23770288  [B
   2:        573164       22737712  [Ljava.lang.Object;
   3:        112029       18155056  <constMethodKlass>
   4:         18478       17027488  <instanceKlassKlass>
   5:         18478       16659952  <constantPoolKlass>
   6:        112029       14353856  <methodKlass>
   7:        357723       14308920  org.jruby.util.ByteList
   8:        190815       14119640  [C
   9:        342470       13698800  org.jruby.RubyString
  10:        307113       12284520  org.jruby.RubyHash$RubyHashEntry
  11:        323719       10359008  org.jruby.RubyObject
  12:         16149        9045216  <constantPoolCacheKlass>
  13:        185448        7417920  org.jruby.RubyFixnum
  14:        217280        6952960  java.util.concurrent.ConcurrentHashMap$HashEntry
  15:         93220        6608504  [Lorg.jruby.runtime.builtin.IRubyObject;
  16:        190049        4561176  java.lang.String
  17:         92681        4448688  org.jruby.RubyArray
...

Using jmap -dump

Note: Getting an .hprof file (Java heap dump) from the Puppet Server service in Puppet Enterprise 2016.2 and later is covered in greater detail in a separate article.

Generate a heap dump (.hprof file) without waiting for an OutOfMemory error using jmap with the -dump option.

The heap dump contains information that can be analyzed to find the causes of abnormal memory usage. If you are diagnosing a memory leak, use the live option. A full garbage collection is performed before the heap is dumped.

For example:

jmap -dump:live,format=b,file=/tmp/jvm_heap_dump.hprof

If you are diagnosing large objects committed to the heap or want to see what’s in the heap, do not use the live option.

For example:

jmap -dump:format=b,file=/tmp/jvm_heap_dump.hprof

The size of the .hprof file generated is large, usually close to the maximum memory that the JVM is allowed to use. For example, if JAVA_ARGS includes -Xmx=4096m, the expected heap dump file size is 4GB, plus or minus a few hundred MB.

The location for your .hprof file, passed with file=, can be adjusted to point anywhere that is writable by the user account passed to su.

# su - pe-puppet -s /bin/bash -c '/opt/puppetlabs/server/apps/java/lib/jvm/java/bin/jmap -dump:live,format=b,file=/tmp/pe_puppetserver.hprof $(systemctl show -p MainPID pe-puppetserver|cut -d= -f2)'

Dumping heap to /tmp/pe_puppetserver.hprof ...

Heap dump file created