About Me

My photo
Rohit leads the Pivotal Labs App Modernization Practice in engineering, delivery training & cross-functional enablement, tooling, scoping, selling, recruiting, marketing, blog posts, webinars and conference sessions. Rohit has led multiple enterprise engagements including ones featured in the Wall Street Journal. Rohit focuses on designing, implementing and consulting with enterprise software solutions for Fortune 500 companies on application migration and modernization.

Saturday, April 9, 2016

Debugging Node.js high CPU, crash and memory issues in Cloud Foundry - part 2

This blog post goes into step-by step run through of how to take a core dump of a specific application instance in cloud foundry. Please note you WILL need access to the PCF OpsManager. Typically the ability to target the BOSH director to your CF deployment is only possessed by sysadmins. So if you are reading this as a developer of Node.js apps in PCF, your best shot is to build the diagnostics into the app like so

  1. Use the restify observable REST framework
  2. Modify the node start command for your app like so node --abort_on_uncaught_exception --expose-gc
  3. Install heapdump with npm install heapdump and require it in server.js. Use chrome dev tools to analyze the heapdumps.
  4. Develop Debugging Techniques as explained here. 
Step 0: App Listing
cf app word-finder
     state     since                    cpu    memory         disk           details
#0   running   2016-04-09 02:13:26 AM   0.0%   107.4M of 1G   164.8M of 1G
#1   running   2016-04-09 10:31:47 PM   0.0%   96.2M of 1G    44.6M of 1G
#2   running   2016-04-09 10:31:47 PM   0.0%   95.4M of 1G    44.6M of 1G

Step 1: Determine app GUID
cf app word-finder --guid
5e46745d-9849-42c3-9549-be9ba5fe1e57

Step 2: Determine Host and Port of the app instance in question
Lets assume that it is instance #2 that is suffering the HIGH CPU.

export CF_TRACE=true
cf curl /v2/apps/5e46745d-9849-42c3-9549-be9ba5fe1e57/stats

  "2": {
      "state": "RUNNING",
      "stats": {
         "name": "word-finder",
         "uris": [
            "word-finder.cfapps.paas.pivotal.io"
         ],
         "host": "10.65.187.46",
         "port": 60540,
         "uptime": 560,
         "mem_quota": 1073741824,
         "disk_quota": 1073741824,
         "fds_quota": 16384,
         "usage": {
            "time": "2016-04-10T02:41:08.873469312Z",
            "cpu": 0.00019609362320671737,
            "mem": 103034880,
            "disk": 46796800
         }
      }
Step 3: bosh ssh into the Diego Cell VM 

ssh into the OpsManager VM and then target the BOSH director to the correct deployment

Target the BOSH director after looking up the Director IP address from the OpsManager console


bosh deployment /var/tempest/workspaces/default/deployments/cf-cdcc8064df9477b983f3.yml

Issue a bosh vms command to determine the name of the Diego cell that houses the app instance container. Note the host-name should match from step-1.

ubuntu@pivotal-ops-manager:~$ bosh vms cf-cdcc8064df9477b983f3 --details
Acting as user 'director' on deployment 'cf-cdcc8064df9477b983f3' on 'p-bosh-1667ec8b8a5e1edbe71b'


| Job/index| State   | Resource Pool | IPs | CID | Agent ID | Resurrection |
|diego_cell-partition-e8ca738002f1f150c602/0 | running | diego_cell-partition-e8ca738002f1f150c602 | 10.65.187.46 | vm-b2f2b447-043b-41ec-bad8-9fd950e9f9d7 | f1ec0fc6-9942-4c18-a55e-b507014684e3 | active       |

ubuntu@pivotal-ops-manager:~$ bosh ssh diego_cell-partition-e8ca738002f1f150c602/0

Step 4: Locate the Garden container that contains the app instance # 2.

First start in the right directory
cd var/vcap/data

Install Veritas
wget https://github.com/pivotal-cf-experimental/veritas/releases/download/latest/veritas
chmod a+x veritas

Configure Veritas
chmod a+x veritas

bosh_4auu9hoye@f1ec0fc6-9942-4c18-a55e-b507014684e3:/var/vcap/data$ ./veritas autodetect
export VITALS_ADDRS=garden:0.0.0.0:17013,rep:0.0.0.0:17008

root@9148d07d-9e64-4308-88ec-6ec90a04be37:/var/vcap/data# export GARDEN_ADDR=/var/vcap/data/garden/garden.sock

root@9148d07d-9e64-4308-88ec-6ec90a04be37:/var/vcap/data# export GARDEN_NETWORK=unix

root@9148d07d-9e64-4308-88ec-6ec90a04be37:/var/vcap/data# export VITALS_ADDRS=garden:0.0.0.0:17013,rep:0.0.0.0:17008

root@9148d07d-9e64-4308-88ec-6ec90a04be37:/var/vcap/data# ./veritas garden-containers

Derive a garden container mapping of the app instances. Now find the garden container based on the port exposed for that instance from step #2.

b60ba43b-d927-4d92-b3775e46745d-9849-42c3-9549-be9ba5fe1e57-773eaa66-667c-40b2-863e-51c3cd9570f8-bf91aa00-fabb-45a9-4311-1e326ad5998e - active @ /var/vcap/data/garden/depot/f8gqc8vnqfl
  Memory: 98.797 MB
  Disk: Total:802.640 MB 0 Inodes, Exclusive:44.629 MB 0 Inodes
  10.254.0.25=>5e46745d-9849-42c3-9549-be9ba5fe1e57-773eaa66-667c-40b2-863e-51c3cd9570f8-bf91aa00-fabb-45a9-4311-1e326ad5998e: 60542:8080,60543:2222
  Running: 2 processes
  Properties:
    executor:owner: executor

5e46745d-9849-42c3-9549-be9ba5fe1e57-773eaa66-667c-40b2-863e-51c3cd9570f8-fc296ea9-1e02-4f97-6c95-553388a3370c - active @ /var/vcap/data/garden/depot/f8gqc8vnqfm
  Memory: 98.297 MB
  Disk: Total:802.640 MB 0 Inodes, Exclusive:44.629 MB 0 Inodes
  10.254.0.29=>5e46745d-9849-42c3-9549-be9ba5fe1e57-773eaa66-667c-40b2-863e-51c3cd9570f8-fc296ea9-1e02-4f97-6c95-553388a3370c: 60540:8080,60541:2222
  Running: 2 processes
  Properties:
    executor:owner: executor

5e46745d-9849-42c3-9549-be9ba5fe1e57-773eaa66-667c-40b2-863e-51c3cd9570f8-8ce28a9f-a9ef-4aff-73a6-4e095822e0db - active @ /var/vcap/data/garden/depot/f8gqc8vnqbr
  Memory: 107.430 MB
  Disk: Total:922.765 MB 0 Inodes, Exclusive:164.754 MB 0 Inodes
  10.254.0.21=>5e46745d-9849-42c3-9549-be9ba5fe1e57-773eaa66-667c-40b2-863e-51c3cd9570f8-8ce28a9f-a9ef-4aff-73a6-4e095822e0db: 60538:8080,60539:2222
  Running: 2 processes
  Properties:
    executor:owner: executor

At this point you have nailed down the path to your specific garden container i.e. /var/vcap/data/garden/depot/f8gqc8vnqfm

Step 5: wsh into the container and issue the gcore command by attaching to the node.js process

Determine the PID of the node.js app process
root@f1ec0fc6-9942-4c18-a55e-b507014684e3:~# cd /var/vcap/data/garden/depot/f8gqc8vnqfm

garden/depot/f8gqc8vnqfm$ sudo su -

root@f1ec0fc6-9942-4c18-a55e-b507014684e3:/var/vcap/data/garden/depot/f8gqc8vnqfm# ./bin/wsh

# ps -ef
UID        PID  PPID  C STIME TTY          TIME CMD
root         1     0  0 02:31 ?        00:00:00 initd -dropCapabilities=false -title="wshd: f8gqc8vnqfm"
vcap        14     1  0 02:31 ?        00:00:00 node server.js
vcap        17     1  0 02:31 ?        00:00:00 /tmp/lifecycle/diego-sshd -address=0.0.0.0:2222 -hostKey=-----BEGIN RSA PRIVATE KEY----- MIICXAIBAAKBgQCxtuDXcInp3mD2x9s8oI6c6Ca8wgEYvPoFwichBYOklyxJHMSy
root       330     1  0 03:07 pts/0    00:00:00 /bin/sh
root       332   330  0 03:08 pts/0    00:00:00 ps -ef

Attach a debugger to the process
# gdb --pid=14
GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
Attaching to process 14
Reading symbols from /home/vcap/app/.heroku/node/bin/node...done.
Reading symbols from /lib/x86_64-linux-gnu/libssl.so.1.0.0...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libssl.so.1.0.0
Reading symbols from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/librt.so.1
Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libdl.so.2
Reading symbols from /usr/lib/x86_64-linux-gnu/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/x86_64-linux-gnu/libstdc++.so.6
Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libm.so.6
Reading symbols from /lib/x86_64-linux-gnu/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libgcc_s.so.1
Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...(no debugging symbols found)...done.
[New LWP 25]
[New LWP 24]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Loaded symbols for /lib/x86_64-linux-gnu/libpthread.so.0
Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
0x00007f8baa3c4859 in syscall () from /lib/x86_64-linux-gnu/libc.so.6


Generate a core dump
(gdb) gcore
warning: target file /proc/14/cmdline contained unexpected null characters
warning: Memory read failed for corefile section, 8192 bytes at 0x7fff6e7d9000.
Saved corefile core.14
(gdb) exit
Undefined command: "exit".  Try "help".
(gdb) quit
A debugging session is active.

Inferior 1 [process 14] will be detached.

Quit anyway? (y or n) y
Detaching from program: /home/vcap/app/.heroku/node/bin/node, process 14


# ls
core.14  firstboot.sh
# ls -al
total 114044
drwx------  2 root root      4096 Apr 10 03:08 .
drwxr-xr-x 31 root root      4096 Apr 10 03:08 ..
-rw-r--r--  1 root root      3106 Feb 20  2014 .bashrc
-rw-r--r--  1 root root       140 Feb 20  2014 .profile
-rw-r--r--  1 root root 116764456 Apr 10 03:08 core.14
-rwxr-xr-x  1 root root       213 Feb 22 19:32 firstboot.sh
#

Step 6 - Transfer core-dump to a VM that has the mdb debugger installed. 
After generating the coredump change ownership of the core to vcap:vcap  and move it to the /tmp dir. so that the core can scp'ed from the container to your Joyent or SunOS box

cf ssh-code | pbcopy scp -P 2222 -o User=cf:0b9216bc-5606-4c40-80cc-ae177a072435/0 ssh.run.haas-35.pez.pivotal.io:/tmp/core.16 . 

Step 7 Load the Core dump on the Solaris VM
Fetch a Solaris VM from the Joyent cloud. My specific machine is a SunOS 6de24ae5-f178-4d11-aa0f-c027c81e9f84 5.11 joyent_20151029T052920Z i86pc i386 i86pc Solaris

# mdb ./node-v4.2.2-linux/node-v4.2.2-linux-x64/bin/node ./core.14

> ::load ./mdb_v8_amd64.so
mdb_v8 version: 1.1.1 (release, from 28cedf2)
V8 version: 143.156.132.195
Autoconfigured V8 support from target
C++ symbol demangling enabled

Step 8 Issue mdb commands for introspecting the dump for stacktraces and data
::help <cmd>
::jsstack
::jsprint
::jssource
::jsconstructor
::findjsobjects
::jsfunctions

Step 9: Figure out the exact stack frame executing on the heap when the crash occurred or High CPU situation occurred.

Happy hunting ... 

No comments:

Post a Comment