remote js-executor: added slow query log, log config on service start

msa/js-executor/api/jsInvokeMessageProcessor.js

@@ -28,6 +28,9 @@ const config = require('config'),
 const scriptBodyTraceFrequency = Number(config.get('script.script_body_trace_frequency'));
 const useSandbox = config.get('script.use_sandbox') === 'true';
 const maxActiveScripts = Number(config.get('script.max_active_scripts'));
+const slowQueryLogMs = Number(config.get('script.slow_query_log_ms'));
+
+const {performance} = require('perf_hooks');
 
 function JsInvokeMessageProcessor(producer) {
     console.log("Producer:", producer);
@@ -39,13 +42,16 @@ function JsInvokeMessageProcessor(producer) {
 }
 
 JsInvokeMessageProcessor.prototype.onJsInvokeMessage = function(message) {
-
+    var tStart = performance.now();
     let requestId;
     let responseTopic;
+    let headers;
+    let request;
+    let buf;
     try {
-        let request = JSON.parse(Buffer.from(message.data).toString('utf8'));
-        let headers = message.headers;
-        let buf = Buffer.from(headers.data['requestId']);
+        request = JSON.parse(Buffer.from(message.data).toString('utf8'));
+        headers = message.headers;
+        buf = Buffer.from(headers.data['requestId']);
         requestId = Utils.UUIDFromBuffer(buf);
         buf = Buffer.from(headers.data['responseTopic']);
         responseTopic = buf.toString('utf8');
@@ -66,6 +72,25 @@ JsInvokeMessageProcessor.prototype.onJsInvokeMessage = function(message) {
         logger.error('[%s] Failed to process request: %s', requestId, err.message);
         logger.error(err.stack);
     }
+
+    var tFinish = performance.now();
+    var tTook = tFinish - tStart;
+
+    if ( tTook > slowQueryLogMs ) {
+        let functionName;
+        if (request.invokeRequest) {
+            try {
+                buf = Buffer.from(request.invokeRequest['functionName']);
+                functionName = buf.toString('utf8');
+            } catch (err){
+                logger.error('[%s] Failed to read functionName from message header: %s', requestId, err.message);
+                logger.error(err.stack);
+            }
+        }
+        logger.warn('[%s] SLOW PROCESSING [%s]ms, functionName [%s], request: ', requestId, tTook, functionName);
+        logger.warn('request: %s', JSON.stringify(request, null, 4))
+    }
+
 }
 
 JsInvokeMessageProcessor.prototype.processCompileRequest = function(requestId, responseTopic, headers, compileRequest) {

msa/js-executor/config/custom-environment-variables.yml

@@ -68,3 +68,4 @@ script:
   use_sandbox: "SCRIPT_USE_SANDBOX"
   script_body_trace_frequency: "SCRIPT_BODY_TRACE_FREQUENCY"
   max_active_scripts: "MAX_ACTIVE_SCRIPTS"
+  slow_query_log_ms: "SLOW_QUERY_LOG_MS"

msa/js-executor/config/default.yml

@@ -55,5 +55,6 @@ logger:
 
 script:
   use_sandbox: "true"
-  script_body_trace_frequency: "1000"
+  script_body_trace_frequency: "1000000"
   max_active_scripts: "1000"
+  slow_query_log_ms: "0.5000" #millis

msa/js-executor/server.js

@@ -15,6 +15,10 @@
  */
 const config = require('config'), logger = require('./config/logger')._logger('main');
 
+logger.info('===CONFIG BEGIN===');
+logger.info(JSON.stringify(config, null, 4));
+logger.info('===CONFIG END===');
+
 const serviceType = config.get('queue_type');
 switch (serviceType) {
     case 'kafka':