Troubleshooting Java applications on OpenShift

$ oc logs tomcat8-4-37683
[...]
Full thread dump OpenJDK 64-Bit Server VM (25.131-b12 mixed mode):
"Attach Listener" #24 daemon prio=9 os_prio=0 tid=0x00007ff2f4001000 nid=0x36 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
"Thread-6" #23 daemon prio=5 os_prio=0 tid=0x00007ff2e8003800 nid=0x26 waiting on condition [0x00007ff2ec3fa000]
   java.lang.Thread.State: WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
	-  parking to wait for  <0x00000000d3b4e070> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
[...]

Jolokia

 Direct connection
 $ curl -k -H "Authorization: Bearer $(oc sa get-token management-admin -n management-infra)" \
           -H "Content-Type: application/json" \
           --cert /etc/origin/master/master.proxy-client.crt \
           --key /etc/origin/master/master.proxy-client.key \
           'https://10.128.1.3:8778/jolokia/' \
           -d '{"mbean":"com.sun.management:type=DiagnosticCommand", "operation":"threadPrint", "arguments":["-l"], "type":"exec"}' \
 | sed 's/\\n/\n/g' | sed 's/\\t/\t/g' > thread.out
 Using the master as reverse proxy
 $ curl -H "Authorization: Bearer $(oc whoami -t)" \
        -H "Content-Type: application/json" \
        'https://osemaster.sandbox.com:8443/api/v1/namespaces/test/pods/https:tomcat8-4-37683:8778/proxy/jolokia/exec/com.sun.management:type=DiagnosticCommand/threadPrint/-l' \
 | sed 's/\\n/\n/g' | sed 's/\\t/\t/g' > thread.out

• Resource consumption

It is often convenient to see how much resources are being consumed by each of the threads listed by the previous command. This can easily be done with the top command:

$ oc exec tomcat8-4-37683 -c tomcat8 -- top -b -n 1 -H -p 1 > top.out
$ cat top.out
top - 07:16:34 up 19:50,  0 users,  load average: 0.00, 0.08, 0.12
Threads:  23 total,   0 running,  23 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2.4 us,  0.7 sy,  0.0 ni, 96.7 id,  0.1 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem :  2915764 total,   611444 free,  1074032 used,  1230288 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  1622968 avail Mem

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
     1 1000060+  20   0 3272048 272060  16084 S  0.0  9.3   0:00.03 java
    15 1000060+  20   0 3272048 272060  16084 S  0.0  9.3   0:09.97 java
    16 1000060+  20   0 3272048 272060  16084 S  0.0  9.3   0:00.14 java

The 9th column shows the CPU consumption and the 10th column shows the memory one per thread.

Using the thread dump analyzer, it is possible to map resource consumption with thread information through the thread id (native-id in TDA).
Additional information on TDA can be found at:

https://github.com/irockel/tda

If you don’t want to use a tool you will need to convert the thread id to hexadecimal to match the nid field in the thread dump. Something like this should do the job:

$ echo "obase=16; <thread-id>" | bc

• Garbage collections

Frequent and long lasting garbage collections may be a symptom of an issue with the application. Full garbage collection may also add unacceptable latency to request processing as it "stops the world". Information gathering on garbage collection is another frequent activity related to troubleshooting performance issues and optimization.

Jstat
Jstat is often used to capture information on garbage collection. Unfortunately, it does not work out of the box with lots of images on OpenShift. The reason for that is that Java stores relevant information in the file /tmp/hsperfdata_. Containers on OpenShift run per default with a high number user id, something like 1000060000 and container in different projects uses different user ids. This is for security reason: this user id won’t match any real user on the host system. It adds an additional protection layer. A consequence of this dynamic allocation of user ids is that there is no match for them in /etc/passwd inside the container, hence the data cannot be stored by the java process into /tmp/hsperfdata_. There are workarounds. One is to have a writable /etc/passwd, which is updated at startup. A finer approach is to use nss wrapper. Jstat will work for instance out of the box with the Jenkins image here.

jstat

$ oc exec tomcat8-4-37683 -- jstat -gcutil 1 10000 5 > jstat.out

Jolokia

 Direct connection
 $ curl -k -H "Authorization: Bearer $(oc sa get-token management-admin -n management-infra)" \
           -H "Content-Type: application/json" \
           --cert /etc/origin/master/master.proxy-client.crt \
           --key /etc/origin/master/master.proxy-client.key \
           'https://10.129.0.2:8778/jolokia/' \
            -d '{"mbean":"java.lang:type=GarbageCollector,name=PS MarkSweep", "attribute":"LastGcInfo", "type":"read"}'
 $ curl -k -H "Authorization: Bearer $(oc sa get-token management-admin -n management-infra)" \
           -H "Content-Type: application/json" \
           --cert /etc/origin/master/master.proxy-client.crt \
           --key /etc/origin/master/master.proxy-client.key \
           'https://10.129.0.2:8778/jolokia/' \
           -d '{"mbean":"java.lang:type=GarbageCollector,name=PS Scavenge", "attribute":"LastGcInfo", "type":"read"}'
 Using the master as reverse proxy
 $ curl -H "Authorization: Bearer $(oc whoami -t)" \
        -H "Content-Type: application/json" \
        'https://osemaster.sandbox.com:8443/api/v1/namespaces/test/pods/https:tomcat8-4-37683:8778/proxy/jolokia/read/java.lang:type=GarbageCollector,name=PS%20MarkSweep/LastGcInfo
 $ curl -H "Authorization: Bearer $(oc whoami -t)" \
        -H "Content-Type: application/json" \
        'https://osemaster.sandbox.com:8443/api/v1/namespaces/test/pods/https:tomcat8-4-37683:8778/proxy/jolokia/read/java.lang:type=GarbageCollector,name=PS%20Scavenge/LastGcInfo

• Evolution in time

If no monitoring solution is in place to gather information required for troubleshooting the commands above can easily be grouped into a script that gets launched at regular intervals to see the dynamic aspects: objects, threads creation, the evolution of memory and CPU consumption, etc. As the creation of a complete heap dump is intrusive it is recommended to limit the memory capture to histograms.

Shooting oneself in the foot

One issue that operation teams often face is that the resolution of an incident has for consequence that the data, which could have been used for identifying the root cause and fixing the underlying problem is lost. ITIL theory says:

• The objective of the Incident Management Lifecycle is to restore the service as quickly as possible to meet SLA.
• The objective of the Problem Management function is to identify the underlying causal factor, which may relate to multiple incidents.

In the case of a dead lock or performance degradation due to a memory leak, the response is often to restart the application to restore to a sane state as quickly as possible. Unfortunately by doing that you have just deleted the application state that could have provided you critical information for the resolution of the underlying problem. I have been more than one time like an astronomer patiently waiting for the comet to come back and in my case the next incident to happen with all my tooling in place for capturing the golden dust of data, which would allow me to identify the cause of the incident… unfortunate. OpenShift provides advanced orchestration capabilities and here again, they can come to the rescue.

Ideally, your application would run with more than a single instance for high availability but even if it were not the case, the following approach would help. The rationale is pretty simple: Instead of killing the faulty container you would just take it out of the request serving pool, the service and route layers in OpenShift. This, unfortunately, would not help if the application were, for instance, consuming from a messaging system. Services and Routes know the pods the requests are to be sent to based on a label/selector mechanism. You just need to change the label on the faulty pod for taking it out of the pods backing the service and processing requests. Let’s look at how it can be done with a quick start.

• Create an application.

  $ oc new-app --name=myapp jboss-webserver30-tomcat8-openshift~https://github.com/openshiftdemos/os-sample-java-web.git

• Scale the deployment to two instances (optional)

  $ oc scale dc myapp --replicas=2

• Change the label on the "faulty" pod

$  oc get pods
NAME              READY     STATUS      RESTARTS   AGE
myapp-1-build     0/1       Completed   0          3m
myapp-1-gd2fn     1/1       Running     0          1m
myapp-1-q1k3n     1/1       Running     0          2m

$ oc describe service myapp
Name:			myapp
Namespace:		test
Labels:			app=myapp
Selector:		app=myapp,deploymentconfig=myapp
Type:			ClusterIP
IP:			172.30.225.169
Port:			8080-tcp	8080/TCP
Endpoints:		10.128.1.6:8080,10.129.0.250:8080
Port:			8443-tcp	8443/TCP
Endpoints:		10.128.1.6:8443,10.129.0.250:8443
Port:			8778-tcp	8778/TCP
Endpoints:		10.128.1.6:8778,10.129.0.250:8778

$ oc label pod myapp-1-gd2fn --overwrite deploymentconfig=mydebug
pod "myapp-1-gd2fn" labeled
$ oc get pods
NAME              READY     STATUS      RESTARTS   AGE
myapp-1-build     0/1       Completed   0          8m
myapp-1-gd2fn     1/1       Running     0          5m
myapp-1-gtstj     1/1       Running     0          5s
myapp-1-q1k3n     1/1       Running     0          7m

$oc describe service myapp
Name:			myapp
Namespace:		test
Labels:			app=myapp
Selector:		app=myapp,deploymentconfig=myapp
Type:			ClusterIP
IP:			172.30.225.169
Port:			8080-tcp	8080/TCP
Endpoints:		10.128.1.7:8080,10.129.0.250:8080
Port:			8443-tcp	8443/TCP
Endpoints:		10.128.1.7:8443,10.129.0.250:8443
Port:			8778-tcp	8778/TCP
Endpoints:		10.128.1.7:8778,10.129.0.250:8778

Immediately after changing the label, OpenShift starts a new pod to satisfy the deployment configuration requirement: to have two running instances → incident resolved. The faulty container is however still running, isolated. You can see in the output above that the new one with the IP 10.128.1.7 in the list of endpoints in the service component has replaced the container with the IP 10.128.1.6.

The service layer is per default implemented through iptables. It is easy to see that the faulty pod is taken out of the service forwarding:

$ iptables -L -n -t nat | grep test/myapp:8080
KUBE-MARK-MASQ  all  --  10.129.0.250 0.0.0.0/0  /* test/myapp:8080-tcp */
DNAT       tcp  --  0.0.0.0/0         0.0.0.0/0  /* test/myapp:8080-tcp */ tcp to:10.129.0.250:8080
KUBE-MARK-MASQ  all  --  10.128.1.7   0.0.0.0/0  /* test/myapp:8080-tcp */
DNAT       tcp  --  0.0.0.0/0         0.0.0.0/0  /* test/myapp:8080-tcp */ tcp to:10.128.1.7:8080

In a similar way, it is possible in OpenShift to look at the HAProxy configuration and see that it has been actualized. You would need to log into the router ("oc rsh ") for that. Here is the relevant part in the configuration file:

/var/lib/haproxy/conf/ haproxy.config

# Plain http backend
backend be_http_test_myapp
[...]
  server 625c4787bdcee4668557b3d7edb1c168 10.128.1.7:8080 check inter 5000ms cookie 625c4787bdcee4668557b3d7edb1c168 weight 100

  server 4c8bc31e32a06e7a7905c04aa02eb97b 10.129.0.250:8080 check inter 5000ms cookie 4c8bc31e32a06e7a7905c04aa02eb97b weight 100

Now that the incident has been resolved, we can use some of the techniques described previously to troubleshoot the application and resolve the problem. When you are finished, the pod can just be killed.

$ oc delete pod myapp-1-gd2fn