Add Operation instanceIx and individual request indexes that are retu…

…rned to the status callback for better tracking of individual calls

Add minLatencyMs to timing.js

README.md

@@ -617,9 +617,19 @@ Example:
 
 #### `statusCallback`
 
-Allows the execution of an extra `statusCallback` function on every request operation completed, this will allow you 
-to know current test results while the test is still running. The results and error passed to the callback are in the
-same format as the results passed to the final callback. 
+Execution this function after every request operation completes. Provides immediate access to test results while the
+test batch is still running. This can be used for more detailed custom logging or developing your own spreadsheet or
+statistical analysis of results.
+
+The results and error passed to the callback are in the same format as the results passed to the final callback.
+
+In addition, the following three properties are added to the `result` OR `error` object:
+
+- `requestElapsed`: time in milliseconds it took to complete this individual request.
+- `requestIndex`: 0-based index of this particular request in the sequence of all requests to be made.
+- `instanceIndex`: the `loadtest(...)` instance index. This is useful if you call `loadtest()` more than once.
+
+You will need to check if `error` is populated in order to determine which object to check for these properties.
 
 Example:
 
@@ -628,6 +638,10 @@ var loadtest = require('loadtest');
 
 function statusCallback(latency, result, error) {
     console.log('Current latency %j, result %j', latency, error ? JSON.stringify(error) + result.toString() : result);
+    console.log('----');
+    console.log('Request elapsed milliseconds: ', error ? error.requestElapsed : result.requestElapsed);
+    console.log('Request index: ', error ? error.requestIndex : result.requestIndex);
+    console.log('Request loadtest() instance index: ', error ? error.instanceIndex : result.instanceIndex);
 }
 
 var options = {

lib/loadtest.js

@@ -167,7 +167,7 @@ function HttpClient(operation, params)
 		{
 			return;
 		}
-		var id = operation.latency.start(id);
+		var id = operation.latency.start();
 		var requestFinished = getRequestFinisher(id);
 		var lib = http;
 		if (options.protocol == 'https:')
@@ -248,7 +248,20 @@ function HttpClient(operation, params)
 			{
 				log.debug('Connection %s ended', id);
 			}
-			operation.latency.end(id, errorCode);
+
+			var elapsed = operation.latency.end(id, errorCode);
+			var index = operation.latency.getRequestIndex(id);
+
+			if (error && typeof error === 'object') {
+				error.requestElapsed = elapsed;
+				error.requestIndex = index;
+				error.instanceIndex = operation.instanceIndex;
+			} else if (result && typeof result === 'object') {
+				result.requestElapsed = elapsed;
+				result.requestIndex = index;
+				result.instanceIndex = operation.instanceIndex;
+			}
+
 			var callback;
 			if (!params.requestsPerSecond)
 			{
@@ -362,6 +375,13 @@ exports.loadTest = function(options, callback)
 	return operation;
 };
 
+/**
+ * Used to keep track of individual load test Operation runs.
+ *
+ * @type {number}
+ */
+var operationInstanceIndex = 0;
+
 /**
  * A load test operation.
  */
@@ -378,6 +398,8 @@ var Operation = function(options, Constructor, callback)
 	var showTimer;
 	var stopTimeout;
 
+	self.instanceIndex = operationInstanceIndex++;
+
 	/**
 	 * Start the operation.
 	 */
@@ -416,7 +438,7 @@ var Operation = function(options, Constructor, callback)
 		}
 
 		if (options.statusCallback) {
-				options.statusCallback(self.latency.getResults(), result, error);
+			options.statusCallback(self.latency.getResults(), result, error);
 		}
 	};
 
@@ -467,7 +489,9 @@ var Operation = function(options, Constructor, callback)
 		});
 		if (callback)
 		{
-			callback(null, self.latency.getResults());
+			var result = self.latency.getResults();
+			result.instanceIndex = this.instanceIndex;
+			callback(null, result);
 		}
 		else
 		{

lib/timing.js

@@ -41,11 +41,15 @@ exports.Latency = function(options, callback)
 	var totalTime = 0;
 	var totalErrors = 0;
 	var maxLatencyMs = 0;
+	var minLatencyMs = 999999;
 	var histogramMs = {};
 	var errorCodes = {};
 	var running = true;
 	var totalsShown = false;
 
+	var requestIndex = 0;
+	var requestIdToIndex = {};
+
 	// init
 	if (options.quiet)
 	{
@@ -56,13 +60,23 @@ exports.Latency = function(options, callback)
 		log.level = Log.DEBUG;
 	}
 
+	/**
+	 * Return the index of the request. This is useful for determining the order
+	 * in which requests returned values.
+	 */
+	self.getRequestIndex = function(requestId) {
+		return requestIdToIndex[requestId];
+	}
+
 	/**
 	 * Start the request with the given id.
 	 */
 	self.start = function(requestId)
 	{
 		requestId = requestId || createId();
 		requests[requestId] = getTime();
+		requestIdToIndex[requestId] = requestIndex++;
+
 		return requestId;
 	};
 
@@ -75,14 +89,17 @@ exports.Latency = function(options, callback)
 		if (!(requestId in requests))
 		{
 			log.error('Message id ' + requestId + ' not found');
-			return;
+			return -2;
 		}
 		if (!running)
 		{
-			return;
+			return -1;
 		}
-		add(getElapsed(requests[requestId]), errorCode);
+
+		var elapsed = getElapsed(requests[requestId]);
+		add(elapsed, errorCode);
 		delete requests[requestId];
+		return elapsed;
 	};
 
 	/**
@@ -113,6 +130,10 @@ exports.Latency = function(options, callback)
 		{
 			maxLatencyMs = rounded;
 		}
+		if (rounded < minLatencyMs)
+		{
+			minLatencyMs = rounded;
+		}
 		if (!histogramMs[rounded])
 		{
 			log.debug('Initializing histogram for %s', rounded);
@@ -218,6 +239,7 @@ exports.Latency = function(options, callback)
 			rps: Math.round(totalRequests / elapsedSeconds),
 			meanLatencyMs: Math.round(meanTime / 10) * 10,
 			maxLatencyMs: maxLatencyMs,
+			minLatencyMs: minLatencyMs,
 			percentiles: self.computePercentiles(),
 			errorCodes: errorCodes
 		};