CODEWITHSUNDEEP
node.jsmemory-leaksibm-cloud
Craig
Craig

Reputation: 1386

Simple node.js app deployed to Bluemix seems to be leaking memory

I am learning node.js, and have a fairly simple application which seems to be leaking memory when deployed to Bluemix. I need assistance in determining if this is caused by my code, or a module I am using.

When deployed with the Monitoring and Cloudant services it would crash with an out of memory error, and be restarted by Bluemix every 12-14 hours - with 256 megs of RAM. I upped the RAM to 1 gig and it still occurs (although less frequently).

When I deploy the app to Bluemix and issue calls to the / route I can see the memory climb slowly up. When testing locally in windows, I do not see the same behavior (testing via process explorer and seeing the amount of private bytes & working set)

I have simplified my app (and removed the monitoring service) and can still reproduce, though the increase is slower with the simplified app.

/*jshint node:true*/

//------------------------------------------------------------------------------
// app.js - Middleware routing
//------------------------------------------------------------------------------

// This application uses express as it's web server
// for more info, see: http://expressjs.com
var express = require( 'express' );

// For handling the POST bodies and multi-part bodies0
var bodyParser = require( 'body-parser' );
var multer = require( 'multer' );

// Create a new express server
var app = express();

// Get the app environment from Cloud Foundry
var cfenv = require( 'cfenv' );
var appEnv = cfenv.getAppEnv();

// Catch all handlers for unhandled URLs
//
app.post( '/*', function( req, res ){
    logRequest( req );
    res.send( 'Unhandled POST received' );
});

app.get( '/*', function( req, res ){
    logRequest( req );
    res.send( 'Unhandled GET received' );
});


// start server on the specified port and binding host
app.listen(appEnv.port, appEnv.bind, function() {

    // print a message when the server starts listening
  console.log("server starting on -- " + appEnv.url);
});

function logRequest(req){
    console.log("Received,"+new Date().toLocaleString()+","+req.method+","+req.originalUrl);
}

Here is the data I gathered, memory is listed in Megs, and I issued requests to the / route:

I tried using the heapdump module, but it fails when being deployed to Bluemix.

cf-node-debug installation now successful - see bottom of question Installed cf-node-debug as suggested, in package.json specified:

  "scripts": {
    "start": "node_modules/.bin/cf-node-debug app.js"
  },

When I pushed the app I got the following:

T13:19:44.08-0400 [STG/39]     OUT -----> Downloaded app package (36K)
T13:19:44.46-0400 [STG/39]     OUT -----> Downloaded app buildpack cache (2.6M)
T13:19:44.80-0400 [STG/0]      OUT     -----> Node.js Buildpack Version: v1.18-20150519-1759
T13:19:44.85-0400 [STG/0]      OUT -----> Resetting git environment
T13:19:45.35-0400 [STG/0]      OUT        TIP: Specify a node version in package.json
T13:19:45.35-0400 [STG/0]      OUT -----> Defaulting to latest stable node: 0.12.2
T13:19:45.35-0400 [STG/0]      OUT -----> Installing IBM SDK for Node.js from cache
T13:19:45.78-0400 [STG/0]      OUT -----> Checking and configuring service extensions
T13:19:45.95-0400 [STG/0]      OUT -----> Restoring node_modules directory from cache
T13:19:46.21-0400 [STG/0]      OUT -----> Pruning cached dependencies not specified in package.json
T13:19:47.22-0400 [STG/0]      OUT -----> Installing dependencies
T13:19:54.50-0400 [STG/0]      OUT        > [email protected] install /tmp/staged/app/node_modules/cf-node-debug/node_modules/node-inspector/node_modules/ws
T13:19:54.50-0400 [STG/0]      OUT        > (node-gyp rebuild 2> builderror.log) || (exit 0)
T13:20:04.31-0400 [STG/0]      OUT        make: Entering directory `/tmp/staged/app/node_modules/cf-node-debug/node_modules/node-inspector/node_modules/ws/build'
T13:20:04.32-0400 [STG/0]      OUT          CXX(target) Release/obj.target/bufferutil/src/bufferutil.o
T13:20:04.71-0400 [STG/0]      OUT          SOLINK_MODULE(target) Release/obj.target/bufferutil.node
T13:20:04.76-0400 [STG/0]      OUT          SOLINK_MODULE(target) Release/obj.target/bufferutil.node: Finished
T13:20:04.77-0400 [STG/0]      OUT          COPY Release/bufferutil.node
T13:20:04.78-0400 [STG/0]      OUT          CXX(target) Release/obj.target/validation/src/validation.o
T13:20:05.15-0400 [STG/0]      OUT          SOLINK_MODULE(target) Release/obj.target/validation.node
T13:20:05.21-0400 [STG/0]      OUT          SOLINK_MODULE(target) Release/obj.target/validation.node: Finished
T13:20:05.21-0400 [STG/0]      OUT          COPY Release/validation.node
T13:20:05.24-0400 [STG/0]      OUT        make: Leaving directory `/tmp/staged/app/node_modules/cf-node-debug/node_modules/node-inspector/node_modules/ws/build'
T13:20:05.29-0400 [STG/0]      OUT        npm WARN deprecated [email protected]: use serve-favicon module
T13:20:05.80-0400 [STG/0]      OUT        [email protected] node_modules/cf-node-debug
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected]
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected]
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected], [email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected], [email protected], [email protected], [email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected], [email protected], [email protected], [email protected], [email protected], [email protected], cookie-signature@1.
@1.0.0, [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected], [email protected])
T13:20:05.80-0400 [STG/0]      OUT        ├── [email protected] ([email protected], [email protected])
T13:20:05.80-0400 [STG/0]      OUT        └── [email protected] ([email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], exp
4.32)
T13:20:06.02-0400 [STG/0]      OUT -----> Caching node_modules directory for future builds
T13:20:06.59-0400 [STG/0]      OUT -----> Cleaning up node-gyp and npm artifacts
T13:20:06.60-0400 [STG/0]      OUT -----> No Procfile found; Adding npm start to new Procfile
T13:20:06.60-0400 [STG/0]      OUT -----> Building runtime environment
T13:20:06.60-0400 [STG/0]      OUT -----> Checking and configuring service extensions
T13:20:06.85-0400 [STG/0]      OUT -----> Installing App Management
T13:20:06.90-0400 [STG/0]      OUT -----> WARN: App Management (Development Mode) cannot be installed because the start script cannot be found.
T13:20:06.91-0400 [STG/0]      OUT        TIP: Specify your start script in 'package.json' or 'Procfile'.
T13:20:06.92-0400 [STG/0]      ERR
T13:20:11.28-0400 [STG/39]     OUT -----> Uploading droplet (20M)
T13:20:20.47-0400 [DEA/39]     OUT Starting app instance (index 0) with guid 1dde346e-4e51-407f-af7b-607772826e72
T13:20:32.91-0400 [App/0]      OUT
T13:20:32.91-0400 [App/0]      OUT > [email protected] start /home/vcap/app
T13:20:32.91-0400 [App/0]      OUT > cf-node-debug app.js
T13:20:33.38-0400 [App/0]      ERR     util.js:634
T13:20:33.38-0400 [App/0]      ERR   ctor.prototype = Object.create(superCtor.prototype, {
T13:20:33.38-0400 [App/0]      ERR                                           ^
T13:20:33.38-0400 [App/0]      ERR TypeError: Cannot read property 'prototype' of undefined
T13:20:33.38-0400 [App/0]      ERR     at Object.exports.inherits (util.js:634:43)
T13:20:33.38-0400 [App/0]      ERR     at Object.<anonymous> (/home/vcap/app/node_modules/cf-node-debug/node_modules/http-proxy/lib/http-proxy/index.js:106:17)
T13:20:33.38-0400 [App/0]      ERR     at Module._compile (module.js:460:26)
T13:20:33.38-0400 [App/0]      ERR     at Object.Module._extensions..js (module.js:478:10)
T13:20:33.38-0400 [App/0]      ERR     at Module.load (module.js:355:32)
T13:20:33.38-0400 [App/0]      ERR     at Function.Module._load (module.js:310:12)
T13:20:33.38-0400 [App/0]      ERR     at Module.require (module.js:365:17)
T13:20:33.38-0400 [App/0]      ERR     at require (module.js:384:17)
T13:20:33.38-0400 [App/0]      ERR     at Object.<anonymous> (/home/vcap/app/node_modules/cf-node-debug/node_modules/http-proxy/lib/http-proxy.js:4:17)
T13:20:33.38-0400 [App/0]      ERR     at Module._compile (module.js:460:26)
T13:20:33.40-0400 [App/0]      ERR npm ERR! Linux 3.13.0-39-generic
T13:20:33.40-0400 [App/0]      ERR npm ERR! argv "/home/vcap/app/vendor/node/bin/node" "/home/vcap/app/vendor/node/bin/npm" "start"
T13:20:33.40-0400 [App/0]      ERR npm ERR! node v0.12.2
T13:20:33.40-0400 [App/0]      ERR npm ERR! npm  v2.7.4
T13:20:33.40-0400 [App/0]      ERR npm ERR! code ELIFECYCLE
T13:20:33.40-0400 [App/0]      ERR npm ERR! [email protected] start: `cf-node-debug app.js`
T13:20:33.40-0400 [App/0]      ERR npm ERR! Exit status 1
T13:20:33.40-0400 [App/0]      ERR npm ERR!
T13:20:33.40-0400 [App/0]      ERR npm ERR! Failed at the [email protected] start script 'cf-node-debug app.js'.
T13:20:33.41-0400 [App/0]      ERR npm ERR! This is most likely a problem with the NodejsStarterApp package,
T13:20:33.41-0400 [App/0]      ERR npm ERR! not with npm itself.
T13:20:33.41-0400 [App/0]      ERR npm ERR! Tell the author that this fails on your system:
T13:20:33.41-0400 [App/0]      ERR npm ERR!     cf-node-debug app.js
T13:20:33.41-0400 [App/0]      ERR npm ERR! You can get their info via:
T13:20:33.41-0400 [App/0]      ERR npm ERR!     npm owner ls NodejsStarterApp
T13:20:33.41-0400 [App/0]      ERR npm ERR! There is likely additional logging output above.
T13:20:33.41-0400 [App/0]      ERR npm ERR! Please include the following file with any support request:
T13:20:33.41-0400 [App/0]      ERR npm ERR!     /home/vcap/app/npm-debug.log
T13:20:33.47-0400 [DEA/39]     ERR Instance (index 0) failed to start accepting connections


$ npm --version
1.4.28  
$ node --version  
v0.10.33

Looks like [email protected] ([email protected])

Note: Using SDK for Node.js from IBM

At Jack's suggestion I tried specifying the engine like:

  "engines": {
    "node": "0.10.x",
    "npm": "2.7.4"
  },

The staging reported: 

2015-06-04T14:27:41.87-0400 [STG/0]      OUT -----> Resetting git environment
2015-06-04T14:27:42.31-0400 [STG/0]      OUT -----> Requested node range:  0.10.x
2015-06-04T14:27:42.31-0400 [STG/0]      OUT -----> Resolved node version: 0.10.38
2015-06-04T14:27:42.31-0400 [STG/0]      OUT -----> Installing IBM SDK for Node.js from cache

but I obtained the same error as before:

2015-06-04T14:28:12.89-0400 [App/0]      ERR util.js:556
2015-06-04T14:28:12.89-0400 [App/0]      ERR   ctor.prototype = Object.create(superCtor.prototype, {
2015-06-04T14:28:12.89-0400 [App/0]      ERR                                           ^
2015-06-04T14:28:12.89-0400 [App/0]      ERR TypeError: Cannot read property 'prototype' of undefined

Update 3:35pm EST

I forked cf-node-debug and modified the http-proxy to 1.11.x. I updated package.json to:

"cf-node-debug": "git://github.com/retinaburn/cf-node-debug.git",

I pushed the app, and now have access to the debug console, but there does not seem to be any heap dumps that I can use to investigate memory leaks.

Upvotes: 3

Views: 1212

Answers (2)

Craig
Craig

Reputation: 1386

I have confirmed that the specified sample app does perform garbage collection in Bluemix with the memory set to 1gb.

I tested using apache bench with 1000 requests to '/' with 10 concurrent transactions.

I suspect the earlier volume tests were too low to trigger a gc.

Upvotes: 0

hohoho
hohoho

Reputation: 230

You may want to isolate your issues. Does this behavior occurs when you are running the application locally? There is a good node-module memwatch that may help. I think memwatch works with node.js 10.x There is a memwatch-next that will work with node.js 0.12.x.

Upvotes: 1

Related Questions