remote js-executor: added metric response sent to queue ms in debug level; parameter added SLOW_QUERY_LOG_BODY="true" to enable log bloat

msa/js-executor/api/jsInvokeMessageProcessor.js

@@ -29,6 +29,7 @@ const scriptBodyTraceFrequency = Number(config.get('script.script_body_trace_fre
 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 slowQueryLogBody = config.get('script.slow_query_log_body') === 'true';
 
 const {performance} = require('perf_hooks');
 
@@ -88,7 +89,9 @@ JsInvokeMessageProcessor.prototype.onJsInvokeMessage = function(message) {
             }
         }
         logger.warn('[%s] SLOW PROCESSING [%s]ms, functionName [%s], request: ', requestId, tTook, functionName);
-        logger.warn('request: %s', JSON.stringify(request, null, 4))
+        if (slowQueryLogBody) {
+            logger.info('Slow request body: %s', JSON.stringify(request, null, 4))
+        }
     }
 
 }
@@ -167,10 +170,13 @@ JsInvokeMessageProcessor.prototype.processReleaseRequest = function(requestId, r
 }
 
 JsInvokeMessageProcessor.prototype.sendResponse = function (requestId, responseTopic, headers, scriptId, compileResponse, invokeResponse, releaseResponse) {
+    var tStartSending = performance.now();
     var remoteResponse = createRemoteResponse(requestId, compileResponse, invokeResponse, releaseResponse);
     var rawResponse = Buffer.from(JSON.stringify(remoteResponse), 'utf8');
     this.producer.send(responseTopic, scriptId, rawResponse, headers).then(
-        () => {},
+        () => {
+            logger.debug('[%s] Response sent to queue, took [%s]ms, scriptId: [%s]', requestId, (performance.now() - tStartSending), scriptId);
+        },
         (err) => {
             if (err) {
                 logger.error('[%s] Failed to send response to queue: %s', requestId, err.message);

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

@@ -69,4 +69,5 @@ 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"
+  slow_query_log_ms: "SLOW_QUERY_LOG_MS" #1.123456
+  slow_query_log_body: "SLOW_QUERY_LOG_BODY" #true or false

msa/js-executor/config/default.yml

@@ -58,4 +58,5 @@ script:
   use_sandbox: "true"
   script_body_trace_frequency: "1000000"
   max_active_scripts: "1000"
-  slow_query_log_ms: "0.5000" #millis
+  slow_query_log_ms: "1.000000" #millis
+  slow_query_log_body: "true"