From 6a4750e302f1f9a4f6fbf54ff8a2fdc01b2b047c Mon Sep 17 00:00:00 2001
From: Redkale <8730487+redkale@users.noreply.github.com>
Date: Fri, 25 Dec 2020 20:30:47 +0800
Subject: [PATCH]

---
 src/org/redkale/mq/HttpMessageProcessor.java | 11 ++++++-----
 src/org/redkale/mq/SncpMessageProcessor.java | 11 ++++++-----
 2 files changed, 12 insertions(+), 10 deletions(-)

diff --git a/src/org/redkale/mq/HttpMessageProcessor.java b/src/org/redkale/mq/HttpMessageProcessor.java
index b8a7d78b4..f88e60701 100644
--- a/src/org/redkale/mq/HttpMessageProcessor.java
+++ b/src/org/redkale/mq/HttpMessageProcessor.java
@@ -89,11 +89,6 @@ public class HttpMessageProcessor implements MessageProcessor {
             long now = System.currentTimeMillis();
             long cha = now - message.createtime;
             long e = now - starttime;
-            if (cha > 50 || e > 10 || finer) {
-                logger.log(Level.FINER, "HttpMessageProcessor.process (mq.delays = " + cha + " ms, mq.blocks = " + e + " ms) message: " + message);
-            } else if (finest) {
-                logger.log(Level.FINEST, "HttpMessageProcessor.process (mq.delay = " + cha + " ms, mq.blocks = " + e + " ms) message: " + message);
-            }
             if (multiconsumer) message.setResptopic(null); //不容许有响应
             HttpContext context = server.getHttpServer().getContext();
             request = new HttpMessageRequest(context, message);
@@ -102,6 +97,12 @@ public class HttpMessageProcessor implements MessageProcessor {
             }
             HttpMessageResponse response = new HttpMessageResponse(context, request, callback, null, null, producer.getProducer(message));
             servlet.execute(request, response);
+            long o = System.currentTimeMillis() - now;
+            if (cha > 50 || e > 10 || o > 50 || finer) {
+                logger.log(Level.FINER, "HttpMessageProcessor.process (mq.delays = " + cha + " ms, mq.blocks = " + e + " ms, mq.executes = " + o + " ms) message: " + message);
+            } else if (finest) {
+                logger.log(Level.FINEST, "HttpMessageProcessor.process (mq.delay = " + cha + " ms, mq.block = " + e + " ms, mq.execute = " + o + " ms) message: " + message);
+            }
         } catch (Throwable ex) {
             if (message.getResptopic() != null && !message.getResptopic().isEmpty()) {
                 HttpMessageResponse.finishHttpResult(finest, request == null ? null : request.getRespConvert(),
diff --git a/src/org/redkale/mq/SncpMessageProcessor.java b/src/org/redkale/mq/SncpMessageProcessor.java
index 54f94e1eb..5080eb2b6 100644
--- a/src/org/redkale/mq/SncpMessageProcessor.java
+++ b/src/org/redkale/mq/SncpMessageProcessor.java
@@ -79,15 +79,16 @@ public class SncpMessageProcessor implements MessageProcessor {
             long now = System.currentTimeMillis();
             long cha = now - message.createtime;
             long e = now - starttime;
-            if (cha > 50 || e > 10 || finer) {
-                logger.log(Level.FINER, "SncpMessageProcessor.process (mq.delays = " + cha + " ms, mq.blocks = " + e + " ms) message: " + message);
-            } else if (finest) {
-                logger.log(Level.FINEST, "SncpMessageProcessor.process (mq.delay = " + cha + " ms, mq.blocks = " + e + " ms) message: " + message);
-            }
             SncpContext context = server.getSncpServer().getContext();
             SncpMessageRequest request = new SncpMessageRequest(context, message);
             response = new SncpMessageResponse(context, request, callback, null, producer.getProducer(message));
             servlet.execute(request, response);
+            long o = System.currentTimeMillis() - now;
+            if (cha > 50 || e > 10 || o > 50 || finer) {
+                logger.log(Level.FINER, "SncpMessageProcessor.process (mq.delays = " + cha + " ms, mq.blocks = " + e + " ms, mq.executes = " + o + " ms) message: " + message);
+            } else if (finest) {
+                logger.log(Level.FINEST, "SncpMessageProcessor.process (mq.delay = " + cha + " ms, mq.block = " + e + " ms, mq.execute = " + o + " ms) message: " + message);
+            }
         } catch (Throwable ex) {
             if (response != null) response.finish(SncpResponse.RETCODE_ILLSERVICEID, null);
             logger.log(Level.SEVERE, SncpMessageProcessor.class.getSimpleName() + " process error, message=" + message, ex instanceof CompletionException ? ((CompletionException) ex).getCause() : ex);