GC Profiling

Author: danielkhan

.DS_Store

@@ -1,7 +1,6 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <module type="WEB_MODULE" version="4">
-  <component name="NewModuleRootManager" inherit-compiler-output="true">
-    <exclude-output />
+  <component name="NewModuleRootManager">
     <content url="file://$MODULE_DIR$" />
     <orderEntry type="sourceFolder" forTests="false" />
     <orderEntry type="library" name="NodeShowcase node_modules" level="project" />

.idea/libraries/NodeShowcase_node_modules.xml

@@ -1,3 +1,5 @@
+// require('./monitoring/dummyagent').init();
+
 
 
 // CPU Profiling
@@ -8,7 +10,7 @@
 
 // See below for callback timings
 
-
+// require('./monitoring/gc').init('./public/metrics');
 
 var express = require('express');
 var path = require('path');
@@ -35,7 +37,7 @@ app.set('view engine', 'jade');
 
 // uncomment after placing your favicon in /public
 //app.use(favicon(__dirname + '/public/favicon.ico'));
-app.use(logger('dev'));
+// app.use(logger('dev'));
 app.use(bodyParser.json());
 app.use(bodyParser.urlencoded({extended: false}));
 app.use(cookieParser());

.idea/misc.xml

@@ -46,7 +46,7 @@ function startProfiling() {
  */
 function stopProfiling(id) {
     var profile = profiler.stopProfiling(id);
-    fs.writeFile(_datadir + '/' + id + '.cpuprofile.json', JSON.stringify(profile), function () {
+    fs.writeFile(_datadir + '/' + id + '.cpuprofile', JSON.stringify(profile), function () {
         console.log('Profiler data written');
     });
 }

.idea/watcherTasks.xml

@@ -10,13 +10,6 @@ var fs = require('fs');
 var profiler = require('v8-profiler');
 var _datadir = null;
 var nextMBThreshold = 0;
-var gcprofiler = require('gc-profiler');
-
-// Listen to GC events
-gcprofiler.on('gc', function (info) {
-    console.log('GC happened');
-    console.log(info);
-});
 
 
 /**
@@ -26,7 +19,7 @@ gcprofiler.on('gc', function (info) {
  */
 module.exports.init = function (datadir) {
     _datadir = datadir;
-    setInterval(tickHeapDump, 5 * 1000);
+    setInterval(tickHeapDump, 500);
 };
 
 /**
@@ -43,9 +36,12 @@ function tickHeapDump() {
  */
 function heapDump() {
     var memMB = process.memoryUsage().rss / 1048576;
+
+    console.log(memMB + '>' + nextMBThreshold);
+
     if (memMB > nextMBThreshold) {
         console.log('Current memory usage: %j', process.memoryUsage());
-        nextMBThreshold += 100;
+        nextMBThreshold += 50;
         var snap = profiler.takeSnapshot('profile');
         saveHeapSnapshot(snap, _datadir);
     }

.idea/workspace.xml

@@ -0,0 +1,79 @@
+'use strict';
+
+var fs = require('fs');
+
+var RuxitAgent = function () {
+    this.linkId = null;
+    this.pathId = null;
+    this.nodeId = null;
+};
+
+var randomId = function () {
+    return Math.floor(Math.random() * (99999 - 10000) + 10000);
+};
+
+RuxitAgent.prototype.createAsyncLink = function () {
+    this.linkId = randomId();
+    fs.writeSync(1, "Async link created " + this.linkId + "\n\n");
+    return this.linkId;
+};
+
+RuxitAgent.prototype.startSubPath = function () {
+    this.pathId = randomId();
+    fs.writeSync(1, "Sub path started " + this.pathId + "\n");
+};
+
+RuxitAgent.prototype.startNode = function (name) {
+    this.nodeId = randomId();
+    fs.writeSync(1, "Node started " + name + " " + this.nodeId + "\n");
+};
+
+RuxitAgent.prototype.endNode = function () {
+    fs.writeSync(1, "Sub path ended " + this.pathId + "\n");
+};
+
+RuxitAgent.prototype.endSubPath = function () {
+    fs.writeSync(1, "Node ended " + this.nodeId + "\n\n");
+};
+
+
+module.exports.init = function () {
+
+    var ruxitAgent = new RuxitAgent();
+    var ruxitTag = ruxitAgent.createAsyncLink();
+
+    var nextTickOrig = process.nextTick;
+    process.nextTick = function (cb) {
+
+
+        var getStack = function (o) {
+            var b, e, s;
+            b = Error.prepareStackTrace;
+
+            Error.prepareStackTrace = function (_, stack) {
+                return stack;
+            };
+            e = new Error;
+            Error.captureStackTrace(e, o);
+            s = e.stack;
+            fs.writeSync(1, s + "\n\n");
+            Error.prepareStackTrace = b;
+            return s;
+        };
+
+        getStack(this);
+
+        arguments[0] = function wrapped() {
+            ruxitAgent.startSubPath(ruxitTag);
+            ruxitAgent.startNode("Callback");
+            try {
+                cb();
+            } finally {
+                ruxitAgent.endNode();
+                ruxitAgent.endSubPath();
+            }
+        };
+
+        nextTickOrig.apply(this, arguments);
+    };
+};

NodeShowcase.iml

@@ -1,18 +1,30 @@
 var gcprofiler = require('gc-profiler');
 var fs = require('fs');
 
+var _datadir = null;
 
+module.exports.init = function (datadir) {
 
-module.exports.init = function (time) {
 
+    var stamp = Date.now();
+    var time = process.hrtime();
+    var runId = Math.round(time[0] * 1e3 + time[1] / 1e6);
+    _datadir = datadir + '/' + runId + '_';
 
-    fs.writeFile("/tmp/gc_Scavenge.csv", 'Start;Duration\n', function (err) {
+    // Preparing CSV files
+    fs.writeFile(_datadir + 'gc_Scavenge.csv', 'Start;Duration\n', function (err) {
         if (err) {
             return console.log(err);
         }
     });
 
-    fs.writeFile("/tmp/gc_MarkSweepCompact.csv", 'Start;Duration\n', function (err) {
+    fs.writeFile(_datadir + 'gc_MarkSweepCompact.csv', 'Start;Duration\n', function (err) {
+        if (err) {
+            return console.log(err);
+        }
+    });
+
+    fs.writeFile(_datadir + 'memory.csv', 'Start;RSS;HeapTotal;HeapUsed\n', function (err) {
         if (err) {
             return console.log(err);
         }
@@ -23,13 +35,29 @@ module.exports.init = function (time) {
 
         var diff = process.hrtime(time);
         var ms = (diff[0] * 1e3 + diff[1] / 1e6);
+        fs.appendFile(_datadir + 'gc_' + info.type + ".csv", (ms - info.duration) + ';' + (info.duration) + "\n", function (err) {
+            if (err) {
+                return console.log(err);
+            }
+        });
+
+    });
 
-        console.log(ms - info.duration);
 
-        fs.appendFile("/tmp/gc_" + info.type + ".csv", (ms - info.duration) + ';' + (info.duration) + "\n", function (err) {
+    var profileMemory = function () {
+        var mem = process.memoryUsage();
+        var diff = process.hrtime(time);
+        var ms = (diff[0] * 1e3 + diff[1] / 1e6);
+        // console.log('append');
+        fs.appendFile(_datadir + "memory.csv", ms + ';' + mem.rss + ';' + mem.heapTotal + ';' + mem.heapUsed + "\n", function (err) {
             if (err) {
                 return console.log(err);
             }
         });
-    });
+    };
+
+    // Profile memory every x ms
+    setInterval(function () {
+        profileMemory()
+    }, 5000);
 };

app.js

@@ -11,10 +11,12 @@
     "cookie-parser": "~1.3.5",
     "debug": "~2.2.0",
     "express": "~4.12.4",
+    "gc-profiler": "^1.3.1",
     "jade": "~1.9.2",
     "less-middleware": "1.0.x",
     "morgan": "~1.5.3",
     "serve-favicon": "~2.2.1",
-    "superagent": "^1.2.0"
+    "superagent": "^1.2.0",
+    "v8-profiler": "^5.3.2"
   }
 }

monitoring/CpuProfiler.js

@@ -82,7 +82,7 @@
     }
 
 
-    d3.json("/metrics/profile-1434177717747.cpuprofile.json", function (error, root) {
+    d3.json("/metrics/profile-1445163184485.cpuprofile", function (error, root) {
         if (error) throw error;
         var path = svg.selectAll("path")
                 .data(partition.nodes(root.head))