Add time information in HelixTask log
Project: http://git-wip-us.apache.org/repos/asf/helix/repo Commit: http://git-wip-us.apache.org/repos/asf/helix/commit/baf383b3 Tree: http://git-wip-us.apache.org/repos/asf/helix/tree/baf383b3 Diff: http://git-wip-us.apache.org/repos/asf/helix/diff/baf383b3 Branch: refs/heads/master Commit: baf383b37c34a2adca27b63c861c0fa48a6a0f25 Parents: 5b55d61 Author: Harry Zhang <[email protected]> Authored: Fri Apr 13 11:36:17 2018 -0700 Committer: Harry Zhang <[email protected]> Committed: Wed Apr 18 16:37:15 2018 -0700 ---------------------------------------------------------------------- .../apache/helix/messaging/handling/HelixTask.java | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/helix/blob/baf383b3/helix-core/src/main/java/org/apache/helix/messaging/handling/HelixTask.java ---------------------------------------------------------------------- diff --git a/helix-core/src/main/java/org/apache/helix/messaging/handling/HelixTask.java b/helix-core/src/main/java/org/apache/helix/messaging/handling/HelixTask.java index 6091e53..7225f70 100644 --- a/helix-core/src/main/java/org/apache/helix/messaging/handling/HelixTask.java +++ b/helix-core/src/main/java/org/apache/helix/messaging/handling/HelixTask.java @@ -22,7 +22,6 @@ package org.apache.helix.messaging.handling; import java.util.Date; import java.util.Map; import java.util.concurrent.ConcurrentHashMap; - import org.apache.helix.AccessOption; import org.apache.helix.HelixDataAccessor; import org.apache.helix.HelixManager; @@ -32,7 +31,6 @@ import org.apache.helix.NotificationContext; import org.apache.helix.NotificationContext.MapKey; import org.apache.helix.PropertyKey; import org.apache.helix.PropertyKey.Builder; -import org.apache.helix.PropertyPathBuilder; import org.apache.helix.messaging.handling.MessageHandler.ErrorCode; import org.apache.helix.messaging.handling.MessageHandler.ErrorType; import org.apache.helix.model.Message; @@ -41,7 +39,6 @@ import org.apache.helix.model.Message.MessageType; import org.apache.helix.monitoring.StateTransitionContext; import org.apache.helix.monitoring.StateTransitionDataPoint; import org.apache.helix.monitoring.mbeans.ParticipantMessageMonitor; -import org.apache.helix.task.TaskResult; import org.apache.helix.util.HelixUtil; import org.apache.helix.util.StatusUpdateUtil; import org.slf4j.Logger; @@ -75,6 +72,8 @@ public class HelixTask implements MessageTask { ErrorType type = null; ErrorCode code = null; + Long handlerStart = null; + Long handlerEnd = null; long start = System.currentTimeMillis(); logger.info("handling task: " + getTaskId() + " begin, at: " + start); @@ -93,7 +92,9 @@ public class HelixTask implements MessageTask { // Handle the message try { setStarted(); + handlerStart = System.currentTimeMillis(); taskResult = _handler.handleMessage(); + handlerEnd = System.currentTimeMillis(); } catch (InterruptedException e) { taskResult = new HelixTaskResult(); taskResult.setException(e); @@ -196,8 +197,14 @@ public class HelixTask implements MessageTask { _statusUpdateUtil.logError(_message, HelixTask.class, errorMessage, _manager); } finally { long end = System.currentTimeMillis(); - logger.info("msg: " + _message.getMsgId() + " handling task completed, results:" - + taskResult.isSuccess() + ", at: " + end + ", took:" + (end - start)); + long totalDuration = end - start; + long handlerDuration = + handlerStart != null && handlerEnd != null ? handlerEnd - handlerStart : -1; + logger.info( + "Message: {} (parent: {}) handling task for {}:{} completed at: {}, results: {}. FrameworkTime: {} ms; HandlerTime: {} ms.", + _message.getMsgId(), _message.getAttribute(Attributes.PARENT_MSG_ID), _message.getResourceName(), + _message.getPartitionName(), end, taskResult.isSuccess(), totalDuration - handlerDuration, + handlerDuration); // Notify the handler about any error happened in the handling procedure, so that // the handler have chance to finally cleanup
