All Things Cloud: 2015-09-27

Thursday, October 1, 2015

Chasing Cloud Foundry OutOfMemory Errors - OOM

If you are ever unfortunate enough to troubleshoot application, java heap or native process OOM issues in Cloud Foundry follow the playbook below to get to the root cause:

1. Include the attached script dump.sh at the root of your JAR/WAR file. You can edit the LOOP_WAIT variable in the script to configure how often it will dump the Java NMT info. I'd suggest somewhere between 5 and 30 seconds, depending on how long it takes for the problem to occur. If the problem happens pretty quick, go with a lower number. If it takes hours, then go with something higher.

2. Make a .profile.d directory, also in the root of the JAR / WAR file. For a detailed explanation on using .profile.d to profile native memory checkout this note from CF support engineer Daniel Mikusa.

3. In that directory, add this script.
#!/bin/bash
$HOME/dump.sh &

This script will be run before the application starts. It starts the dump.sh script and backgrounds it. The dump.sh script will loop and poll the Java NMT stats, dumping them to STDOUT. As an example see the simple-java-web-for-test application. There is also an accompanying load plan here.

4. Add the following parameters to JAVA_OPTS:
JAVA_OPTS: "-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./jvm-gc.log -XX:NativeMemoryTracking=detail"
The -XX:NativeMemoryTracking will enable native OOM analysis [1]. More on this later. The -Xloggc will allow you to pipe all GC output to a log that you can later analyze with tool like PMAT or GCMV

5. Push or restage the application.

6. In a terminal open cf logs app-name > app-name.log. That will dump the app logs & the Java NMT info to the file. Please try to turn off as much application logging as possible as this will make it easier to pick out the Java NMT dumps.

7. Kick off the load tests.

The nice thing about Java NMT is that it will take a snapshot of the memory usage when it first runs and every other time we poll the stats we'll see a diff of the initial memory usage. This is helpful as we really only need the last Java NMT dump prior to the crash to know what parts of the memory have increased and by how much. It's also nice because it gives us insight into non-heap usage. Given the Java NMT info, it should be easier to make some suggestions for tuning the JVM so that it doesn't exceed the memory limit of the application and cause a crash.

8. If you have the ability to ssh into the container use the following commands to trigger heapdumps and coredumps
JVM Process Id:
PID=` ps -ef | grep java | grep -v "bash\|grep" | awk '{print $2}'`
Heapdump:
./jmap -dump:format=b,file=/home/vcap/app/test.hprof $PID

Coredump:

kill -6 $PID should produce a core file and leave the server running

Analyze these dumps using tools like Eclipse Memory Analyzer and IBM HeapDump Analyzer

9. If you have the ability to modify the application then enable the Spring Boot Actuator feature for your app if it is Boot app else integrate a servlet or script like DumpServlet and HeapDumpServlet into the app

Salient Notes:

- The memory statistics reported by CF in cf app is in fact used_memory_in_bytes which is a summation of rss and the active and inactive caches. [2] and [3]. This is the number watched by the cgroup linux OOM killer.
- The Cloud Foundry Java Buildpack by default enables the following parameter -XX:OnOutOfMemoryError=$PWD/.java-buildpack/open_jdk_jre/bin/killjava.sh
Please do NOT be lulled into a false sense of complacency by this parameter. I have never seen this work in production. Your best bet is to be proactive when triggering and pulling dumps using servlets, JMX, kill commands, whatever ...

References:

[1] https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr007.html

[2] https://github.com/cloudfoundry/dea_ng/commit/e5fd523aaf2cddeda01d4134ecd2a929829c4147

[3] https://groups.google.com/a/cloudfoundry.org/d/msg/vcap-dev/6M8BDV_tq7w/VCoJmWtJJncJ
[4] https://blogs.oracle.com/poonam/entry/about_g1_garbage_collector_permanent
[5] http://www.linuxdevcenter.com/pub/a/linux/2006/11/30/linux-out-of-memory.html
[6] Native Memory Best Practices
[7] http://www-01.ibm.com/support/docview.wss?uid=swg21255223
[8] https://publib.boulder.ibm.com/httpserv/cookbook/cookbook.html

Tuesday, September 29, 2015

Spring Boot Activator metrics collection in a spreadsheet

If your app is a spring boot app that has the actuator enabled then use this nifty script from Greg Turnquist's Learning Spring Boot book with some changes from me to collect all the metrics in a csv

package learningspringboot

@Grab("groovy-all")
import groovy.json.*

package learningspringboot

@Grab("groovy-all")
import groovy.json.*

@EnableScheduling
class MetricsCollector {

def url = "http://fizzbuzz.cfapps.io/metrics"
def slurper = new JsonSlurper()
def keys = slurper.parse(new URL(url)).keySet()
def header = false;
@Scheduled(fixedRate = 1000L)
void run() {
if (!header) {
println(keys.join(','))
header = true
}

def metrics = slurper.parse(new URL(url))

println(keys.collect{metrics[it]}.join(','))
}
}

Debugging DEA Issues on Cloud Foundry - Halloween Edition

Ever wondered why Cloud Foundry does not support ssh'ing into the warden container. Such a feature could be useful in so many situations - TechOps, Troubleshooting, Debugging etc. cf-ssh is coming to Cloud Foundry via Diego; however till you deploy Diego in production you will need to live with the process below to ssh into a particular application instance warden container.

# Step 1 - Find app guid

C:\Users\Administrator\workspace\FizzBuzz>cf app --guid fizzbuzz
90291bd7-ce52-43ee-aaa1-ed0405863c4a

# Step 2 - Find DEA IP address and port

C:\Users\Administrator\workspace\FizzBuzz>cf curl /v2/apps/90291bd7-ce52-43ee-aaa1-ed0405863c4a/stats
{
"0": {
"state": "RUNNING",
"stats": {
"name": "fizzbuzz",
"uris": [
"fizzbuzz.kelapure.cloud.pivotal.io"
],
"host": "192.168.200.27",
"port": 61015,
"uptime": 1489673,
"mem_quota": 1073741824,
"disk_quota": 1073741824,
"fds_quota": 16384,
"usage": {
"time": "2015-09-29 02:36:12 +0000",
"cpu": 0.003104336638753874,
"mem": 546877440,
"disk": 187445248
}
}
}
}

# Step 3 - Locate DEA Job that maps to the DEA IP from previous step

# Step 4 Login into the DEA VM

ubuntu@pivotal-ops-manager:~$ bosh ssh dea-partition-0d7a243620d08147fd3a/0 --public_key y.pub
Acting as user 'director' on deployment 'cf-938e3d9bec67dbffeacc' on 'microbosh-38a3a7433db69fa7d159'
Enter password (use it to sudo on remote host): ********
Target deployment is `cf-938e3d9bec67dbffeacc'

see https://github.com/cloudfoundry/bosh-lite/issues/134 if stuck on bosh ssh

# Step 5 Locate the warden container path

If you grep for `fizzbuzz`and the instance port gleaned from step-2 in the list below you will find the following

"warden_container_path": "/var/vcap/data/warden/depot/18tlhc59f3v",

bosh_yms06qjkj@437bbc76-7d1c-4ce9-916d-4e6a6355537f:/var/vcap/data/warden/depot$ sudo cat /var/vcap/data/dea_next/db/instances.json

[sudo] password for bosh_yms06qjkj:
{
"time": 1443494275.6732097,
"instances": [

{
"cc_partition": "default",
"instance_id": "07a4a39d7ec14249863303246c73dfa2",
"instance_index": 0,
"private_instance_id": "5e15175c18644561828e52534b7c7a71fad5773f13b045058eaed76793618b1f",
"warden_handle": "18tlhc59erj",
"limits": {
"mem": 512,
"disk": 1024,
"fds": 16384
},
"health_check_timeout": null,
"environment": {
"CF_PROCESS_TYPE": "web"
},
"services": [

],
"application_id": "093a9e11-0b06-45f1-b3c4-e801ad0aca81",
"application_version": "2febead7-c0fe-43a5-b4a4-724c5581c037",
"application_name": "tmfnodetest",
"application_uris": [
"tmfnodetest.kelapure.cloud.pivotal.io"
],
"droplet_sha1": "fcba91c3099ba1218febfcb043d3792ccc9bba97",
"droplet_uri": null,
"start_command": null,
"state": "RUNNING",
"warden_job_id": 461,
"warden_container_path": "/var/vcap/data/warden/depot/18tlhc59erj",
"warden_host_ip": "10.254.2.41",
"warden_container_ip": "10.254.2.42",
"instance_host_port": 61127,
"instance_container_port": 61127,
"syslog_drain_urls": [

],
"state_starting_timestamp": 1442435859.1693246
},

{
"cc_partition": "default",
"instance_id": "9383f43f0e3549ad9c29c511c5f4211e",
"instance_index": 0,
"private_instance_id": "23065b9faddb43d2ae296802c1db8cbdbf2a2d00dd2343849c8825bcfc7eb044",
"warden_handle": "18tlhc59enu",
"limits": {
"mem": 1024,
"disk": 1024,
"fds": 16384
},
"health_check_timeout": null,
"environment": {
"CF_PROCESS_TYPE": "web"
},
"services": [
{
"credentials": {
"agent-name": "nginx-hello",
"host-name": "ca-apm.springapps.io",
"port": "5001"
},
"options": {

},
"syslog_drain_url": "",
"label": "user-provided",
"name": "ca_apm_10",
"tags": [

]
}
],
"application_id": "90291bd7-ce52-43ee-aaa1-ed0405863c4a",
"application_version": "09f093ae-c9e8-46ba-89c8-e56d7b84b671",
"application_name": "fizzbuzz",
"application_uris": [
"fizzbuzz.kelapure.cloud.pivotal.io"
],
"droplet_sha1": "e5fc94cc79eb72489e94c6b620887c5b72244b89",
"droplet_uri": "http://staging_upload_user:c601ae7f5ae3745d40ee@192.168.200.18:9022/staging/droplets/90291bd7-ce52-43ee-aaa1-ed0405863c4a/download",
"start_command": null,
"state": "RUNNING",
"warden_job_id": 92,
"warden_container_path": "/var/vcap/data/warden/depot/18tlhc59enu",
"warden_host_ip": "10.254.0.85",
"warden_container_ip": "10.254.0.86",
"instance_host_port": 61015,
"instance_container_port": 61015,
"syslog_drain_urls": [
""
],
"state_starting_timestamp": 1442004499.0728624

},

{
"cc_partition": "default",
"instance_id": "fa057152a7094ee6bfd0cd28c8cb76dc",
"instance_index": 0,
"private_instance_id": "18b2515c046742ae979fbfa58428120608960bc04f7444759983d1c91621e7da",
"warden_handle": "18tlhc59f3v",
"limits": {
"mem": 1024,
"disk": 1024,
"fds": 16384
},
"health_check_timeout": null,
"environment": {
"CF_PROCESS_TYPE": "web"
},
"services": [

],
"application_id": "d9969088-1f7b-40b3-a048-c71814d172c4",
"application_version": "431e7f3d-774b-4c24-ad4e-c6fda884dab1",
"application_name": "spring-music",
"application_uris": [
"spring-music.kelapure.cloud.pivotal.io"
],
"droplet_sha1": "9e35ddfd97a7c1a32e2a69d5e1c5f90c6d4b7e06",
"droplet_uri": "http://staging_upload_user:c601ae7f5ae3745d40ee@192.168.200.18:9022/staging/droplets/d9969088-1f7b-40b3-a048-c71814d172c4/download",
"start_command": null,
"state": "CRASHED",
"warden_job_id": 1265,
"warden_container_path": "/var/vcap/data/warden/depot/18tlhc59f3v",
"warden_host_ip": "10.254.2.113",
"warden_container_ip": "10.254.2.114",
"instance_host_port": 61395,
"instance_container_port": 61395,
"syslog_drain_urls": [

],
"state_starting_timestamp": 1443494262.4416354
}
],
"staging_tasks": [

]
}

# Step 6 wsh into the warden container

bosh_yms06qjkj@437bbc76-7d1c-4ce9-916d-4e6a6355537f:/var/vcap/data/warden/depot$ cd 18tlhc59enu

bosh_yms06qjkj@437bbc76-7d1c-4ce9-916d-4e6a6355537f:/var/vcap/data/warden/depot/18tlhc59enu$ ls
bin destroy.sh etc jobs lib mnt net_rate.sh net.sh run setup.sh snapshot.json start.sh stop.sh tmp

bosh_yms06qjkj@437bbc76-7d1c-4ce9-916d-4e6a6355537f:/var/vcap/data/warden/depot/18tlhc59enu$ sudo ./bin/wsh
wsh wshd

bosh_yms06qjkj@437bbc76-7d1c-4ce9-916d-4e6a6355537f:/var/vcap/data/warden/depot/18tlhc59enu$ sudo ./bin/wsh
root@18tlhc59enu:~# ls
firstboot.sh
root@18tlhc59enu:~# cd /home
root@18tlhc59enu:/home# cd vcap/
root@18tlhc59enu:/home/vcap# ls
app logs run.pid staging_info.yml tmp

root@18tlhc59enu:/home/vcap# ll
total 40
drwxr-xr-x 5 vcap vcap 4096 Sep 11 20:48 ./
drwxr-xr-x 3 root root 4096 Sep 11 20:48 ../
drwxr--r-- 7 vcap vcap 4096 Sep 11 20:47 app/
-rw-r--r-- 1 vcap vcap 220 Apr 9 2014 .bash_logout
-rw-r--r-- 1 vcap vcap 3637 Apr 9 2014 .bashrc
drwxr-xr-x 2 vcap vcap 4096 Sep 11 20:47 logs/
-rw-r--r-- 1 vcap vcap 675 Apr 9 2014 .profile
-rw------- 1 vcap vcap 3 Sep 11 20:48 run.pid
-rw-r--r-- 1 vcap vcap 2000 Sep 11 20:47 staging_info.yml
drwxr-xr-x 3 vcap vcap 4096 Sep 11 20:48 tmp/
root@18tlhc59enu:/home/vcap#

# Step 7 - Now you are free to ftp files out or take heap dumps or thread-dumps

For instance to take a heapdump
root@18tlhc59enu:/home/vcap/app/.java-buildpack/open_jdk_jre/bin# ll
total 384
drwxr-xr-x 2 vcap vcap 4096 Sep 11 20:47 ./
drwxr-xr-x 5 vcap vcap 4096 Sep 11 20:47 ../
-rwxr-xr-x 1 vcap vcap 8798 Jul 16 09:29 java*
-rwxr-xr-x 1 vcap vcap 8909 Jul 16 09:29 jcmd*
-rwxr-xr-x 1 vcap vcap 8909 Jul 16 09:29 jjs*
-rwxr-xr-x 1 vcap vcap 8973 Jul 16 09:29 jmap*
-rwxr-xr-x 1 vcap vcap 8981 Jul 16 09:29 jstack*
-rwxr-xr-x 1 vcap vcap 8917 Jul 16 09:29 keytool*
-rwxr-xr-x 1 vcap vcap 1146 Sep 11 20:47 killjava.sh*
-rwxr-xr-x 1 vcap vcap 8981 Jul 16 09:29 orbd*
-rwxr-xr-x 1 vcap vcap 8917 Jul 16 09:29 pack200*
-rwxr-xr-x 1 vcap vcap 8917 Jul 16 09:29 policytool*
-rwxr-xr-x 1 vcap vcap 8909 Jul 16 09:29 rmid*
-rwxr-xr-x 1 vcap vcap 8917 Jul 16 09:29 rmiregistry*
-rwxr-xr-x 1 vcap vcap 8917 Jul 16 09:29 servertool*
-rwxr-xr-x 1 vcap vcap 8989 Jul 16 09:29 tnameserv*
-rwxr-xr-x 1 vcap vcap 217462 Jul 16 09:29 unpack200*

root@18tlhc59enu:/home/vcap/app/.java-buildpack/open_jdk_jre/bin# su vcap

vcap@18tlhc59enu:~/app/.java-buildpack/open_jdk_jre/bin$ PID=` ps -ef | grep java | grep -v "bash\|grep" | awk '{print $2}'`
vcap@18tlhc59enu:~/app/.java-buildpack/open_jdk_jre/bin$ echo $PID
29

vcap@18tlhc59enu:~/app/.java-buildpack/open_jdk_jre/bin$ ./jmap -dump:format=b,file=/home/vcap/app/test.hprof $PID
Dumping heap to /home/vcap/app/test.hprof ...
Heap dump file created

vcap@18tlhc59enu:~/app/.java-buildpack/open_jdk_jre/bin$ ls -al /home/vcap/app
total 230616
drwxr--r-- 7 vcap vcap 4096 Sep 29 03:06 .
drwxr-xr-x 5 vcap vcap 4096 Sep 11 20:48 ..
drwxr-xr-x 5 vcap vcap 4096 Sep 11 20:47 .java-buildpack
-rw-r--r-- 1 vcap vcap 82155 Sep 11 20:47 .java-buildpack.log
drwxr--r-- 3 vcap vcap 4096 Sep 11 20:46 META-INF
drwxr--r-- 3 vcap vcap 4096 Sep 11 20:46 my-resources
drwxr--r-- 3 vcap vcap 4096 Sep 11 20:46 org
-rw------- 1 vcap vcap 236032777 Sep 29 03:06 test.hprof
drwxr--r-- 5 vcap vcap 4096 Sep 11 20:46 WEB-INF

All Things Cloud

About Me

Thursday, October 1, 2015

Chasing Cloud Foundry OutOfMemory Errors - OOM

Tuesday, September 29, 2015

Spring Boot Activator metrics collection in a spreadsheet

Monday, September 28, 2015

Debugging DEA Issues on Cloud Foundry - Halloween Edition

# Step 3 - Locate DEA Job that maps to the DEA IP from previous step

# Step 5 Locate the warden container path

# Step 6 wsh into the warden container

Thursday, October 1, 2015

Chasing Cloud Foundry OutOfMemory Errors - OOM

Tuesday, September 29, 2015

Spring Boot Activator metrics collection in a spreadsheet

Monday, September 28, 2015

Debugging DEA Issues on Cloud Foundry - Halloween Edition

# Step 3 - Locate DEA Job that maps to the DEA IP from previous step

# Step 5 Locate the warden container path

# Step 6 wsh into the warden container