diff --git a/msa/js-executor/api/jsInvokeMessageProcessor.js b/msa/js-executor/api/jsInvokeMessageProcessor.js index acba87ba57..d706e0adde 100644 --- a/msa/js-executor/api/jsInvokeMessageProcessor.js +++ b/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) { diff --git a/msa/js-executor/config/custom-environment-variables.yml b/msa/js-executor/config/custom-environment-variables.yml index 15c4e37fc0..848351217b 100644 --- a/msa/js-executor/config/custom-environment-variables.yml +++ b/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" diff --git a/msa/js-executor/config/default.yml b/msa/js-executor/config/default.yml index fd60364247..8ada8f691b 100644 --- a/msa/js-executor/config/default.yml +++ b/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 diff --git a/msa/js-executor/server.js b/msa/js-executor/server.js index fcec2820a4..0c415cc156 100644 --- a/msa/js-executor/server.js +++ b/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':